ddvk / remarkable2-framebuffer

remarkable2 framebuffer reversing
MIT License
276 stars 22 forks source link

[ioctl] add implementation of wait ioctl using semaphores #45

Closed raisjn closed 3 years ago

raisjn commented 3 years ago

testing:

snelg commented 3 years ago

Hmm, still does the corrupted drawing I showed in https://github.com/ddvk/remarkable2-framebuffer/issues/38#issuecomment-770454729

Client output:

1612888136211 MSG Q SEND 492 769 418 95
1612888136268 MSG Q SEND 147 589 1110 694
CLIENT: sync
FINISHED WAIT IOCTL 0.000544875
1612888136333 MSG Q SEND 492 769 418 95

Server output:

1608593168910ms MSG Q RECV 492 769 418 95
Dirty Region: 492 769 418 95
doUpdate
mxc: waveform_mode 1
mxc: update mode 0
mxc: update marker 4
final: waveform 1 flags 4

1612888136212 Total Update took 0.000664875s
1608593168968ms MSG Q RECV 147 589 1110 694
Dirty Region: 147 589 1110 694
doUpdate
mxc: waveform_mode 3
mxc: update mode 0
mxc: update marker 5
final: waveform 3 flags 0

1612888136291 Total Update took 0.0218848s
1608593168990ms MSG Q RECV 1999528550 846033455 779381089 3748149
1608593169033ms MSG Q RECV 492 769 418 95
Dirty Region: 492 769 418 95
doUpdate
mxc: waveform_mode 3
mxc: update mode 0
mxc: update marker 6
final: waveform 3 flags 0

1612888136334 Total Update took 0.000672375s
raisjn commented 3 years ago

thanks, that's very helpful! in local testing, the semaphore based wait has variable timing (from 0.5ms -> 150+ms), but it looks like we are still not correctly waiting enough time in this case for KOReader. (i'm assuming the 20ms is the draw we are incorrectly not waiting for)

can you add a logging line on the server side to see where the WAIT sync is happening? it should have happened after the line 1612888136291 Total Update took 0.0218848s, but it must be happening before or somewhere else.

snelg commented 3 years ago

Wasn't sure if it was necessary to log both "before" and "after", so here's what came out with additional logging wrapped around the fb.WaitForLastUpdate() call in server_main

1608610205257ms MSG Q RECV 492 769 418 95
Dirty Region: 492 769 418 95
doUpdate
mxc: waveform_mode 1
mxc: update mode 0
mxc: update marker 4
final: waveform 1 flags 4

1612905172559 Total Update took 0.000798s
1608610205322ms MSG Q RECV 147 589 1110 694
Dirty Region: 147 589 1110 694
doUpdate
mxc: waveform_mode 3
mxc: update mode 0
mxc: update marker 5
final: waveform 3 flags 0

1612905172649 Total Update took 0.0263809s
1608610205349ms MSG Q RECV 1999528550 846033455 779381089 3289651
1612905172651 Before WaitForLastUpdate
1612905172651 After WaitForLastUpdate
1608610205375ms MSG Q RECV 492 769 418 95
Dirty Region: 492 769 418 95
doUpdate
mxc: waveform_mode 3
mxc: update mode 0
mxc: update marker 6
final: waveform 3 flags 0

1612905172677 Total Update took 0.000663125s
raisjn commented 3 years ago

i think that i updated to using the sem_timedwait incorrectly and didn't test it properly. sem_timedwait takes a time since epoch (abs_timeout), i thought it just takes an amount of time to wait.

if we go back to sem_wait() or use sem_timedwait() properly it will hopefully work.

i'm a bit stumped as to why the wait ioctl is not saying it took as long as the draw right before it. my understanding is:

* koreader draw 1 happens (492 769 418 95) - 0.7ms * koreader draw 2 happens (147 589 1110 694) - this one is relatively expensive at 20ms * wait ioctl is called - this says it only waited 0.5ms but it should have waited 20ms * koreader draw 3 happens (492 769 418 95) - 0.6ms

on the server, everything is processed in a loop. so when it says that draw 2 took 20ms, the processing of all items in the queue has to wait 20ms

snelg commented 3 years ago

Yes, proper sem_timedwait() works great. PR #46 opened :)

snelg commented 3 years ago

Hmm, wait, no, it only works part of the time...? I probably don't understand the clock_gettime properly, and/or timespec manipulation is a little more complicated or something. Doing more fiddling.

raisjn commented 3 years ago

in the discussion on #46, it is determined that sem_wait does work properly. this diff needs to be rebased, though, since @matteodelabre's diff has landed

raisjn commented 3 years ago

i'm seeing merge conflicts. maybe better if @snelg opens up merge against master and we continue on there? (and again, thanks snelg for all the help)

one piece i think i might want to add is an environment variable to turn off the wait signal, so if there is an issue, we can give instructions on how to disable. (for example: RM2FB_NO_WAIT could skip the client shim's wait path)

snelg commented 3 years ago

Yeah, not sure what went wonky in the merge commits. The squashed merge I just made for #49 has an empty diff with this branch. :shrug: