Re: Obscure timing issue

[Fred Kiefer]

I found your analysis very interesting, although I will need more time
to understand it in detail. I may not be able to answer all of your
questions, but there is one where I think I am able to help.

What triggers the redraw?
This is caused by the code in NSControl mouseDown: here we set the cell
to highlighted and mark the control as needing display. This gets picked
up by the _handleAutodisplay: mechanism on NSWindow. This is very likely
to happen when the run loop has nothing else to do.

Fred

Wolfgang Lux wrote:
> Lately I've been tracking down a rather obscure timing issue which
> manifests itself -- at least -- by a delayed processing of events.
> For instance, if I click a button very quickly, the button gets
> highlighted upon the ButtonPress event, but it remains highlighted
> and the ButtonRelease event is recognized only upon the next event,
> e.g., after clicking the button again or moving the mouse.
> 
> With the help of running Ink --GNU-Debug=NSEvent --GNU-Debug=NSRunLoop
> and ktrace'ing the process, I think I understand the problem now, but
> do not have a solution. I'll try to explain the issue with the relevant
> part of the debug output of the Ink process starting at the point before
> I click the Cancel button of the Open Panel.
> 
> 2008-12-09 21:38:24.690 Ink[23177] File NSRunLoop.m: 1075. In [NSRunLoop
> -limitDateForMode:] limit date 250547922.969250 in NSDefaultRunLoopMode
> 2008-12-09 21:38:24.691 Ink[23177] File NSRunLoop.m: 1168. In [NSRunLoop
> -acceptInputForMode:beforeDate:] accept I/P before 250547922.928673 (sec
> from now 18.237913) in NSDefaultRunLoopMode
> 2008-12-09 21:38:24.692 Ink[23177] File GSRunLoopCtxt.m: 753. In
> [GSRunLoopCtxt -pollUntil:within:] listening to 1 port sockets
> 2008-12-09 21:38:24.692 Ink[23177] File GSRunLoopCtxt.m: 753. In
> [GSRunLoopCtxt -pollUntil:within:] listening to 1 port sockets
> 
> Now I click the Cancel button.
> 
> 2008-12-09 21:38:37.244 Ink[23177] File GSRunLoopCtxt.m: 792. In
> [GSRunLoopCtxt -pollUntil:within:] select returned 1
> 
> The ktrace output shows that Ink reads the ButtonPress event from the
> X connection socket at this point.
> 
> 2008-12-09 21:38:37.245 Ink[23177] 23068699 ButtonPress:        
> xEvent.xbutton.time 545621211 timeOfLastClick 545549217
> 2008-12-09 21:38:37.247 Ink[23177] File NSRunLoop.m: 1190. In [NSRunLoop
> -acceptInputForMode:beforeDate:] accept I/P completed in
> NSDefaultRunLoopMode
> 2008-12-09 21:38:37.248 Ink[23177] Send NSEvent type: 1 to window 6
> 
> Clicking the button causes the button's cell to enter a mouse tracking
> event loop at this point. This code uses XPending in order to process
> any events that are already available on the X event queue, but apparently
> the queue is empty at this point in my case. Thus the code asks NSRunLoop
> for the next event.
> 
> 2008-12-09 21:38:37.252 Ink[23177] File NSRunLoop.m: 1075. In [NSRunLoop
> -limitDateForMode:] limit date 63113990400.000000 in EventTrackingMode
> 
> At this point, the gui appears to highlight the clicked button. At least
> the ktrace output shows that the process attempts to read the directories
> ThemeTiles, ThemeTiles/German.lproj, and ThemeTiles/English.lproj in the
> gui's Resources directory multiple times, which all don't exist on my
> system, and then it writes a lot of data to the X connection socket (in
> fact, it is sending about 500 kByte to the server; this looks like it is
> redrawing the whole open panel and not only the Cancel button). The
> important
> point is that at the time when the backend starts writing the data to the
> X server, the ButtonRelease event is available on the X socket and read
> into the X event queue by the X library code. Thus, no data is available
> on the X connection socket when the run loop invokes the poll or select
> system call and it starts waiting for the next event ...
> 
> 2008-12-09 21:38:37.480 Ink[23177] File NSRunLoop.m: 1168. In [NSRunLoop
> -acceptInputForMode:beforeDate:] accept I/P before 63113990400.000000
> (sec from now 62863442482.519943) in EventTrackingMode
> 
> ... until I finally click the button again.
> 
> 2008-12-09 21:38:59.989 Ink[23177] File GSRunLoopCtxt.m: 792. In
> [GSRunLoopCtxt -pollUntil:within:] select returned 1
> 
> Now the ButtonRelease event, which is already in the X event queue is
> getting processed. The ktrace output proves that the event is already
> in the queue because no I/O occurs at this point.
> 
> 2008-12-09 21:38:59.990 Ink[23177] 23068699 ButtonRelease
> 
> And now the next event, which caused the select system call to return,
> is read from the socket as witnessed by the ktrace output.
> 
> 2008-12-09 21:38:59.991 Ink[23177] 23068699 ButtonPress:        
> xEvent.xbutton.time 545643407 timeOfLastClick 545621211
> 2008-12-09 21:38:59.995 Ink[23177] File NSRunLoop.m: 1190. In [NSRunLoop
> -acceptInputForMode:beforeDate:] accept I/P completed in EventTrackingMode
> 2008-12-09 21:39:00.503 Ink[23177] 23068699 ButtonRelease
> 
> I do not know where exactly the redrawing code is invoked between the
> start of NSRunLoop's -runMode:beforeDate: and the poll/select call in
> GSRunLoopCtxt's -pollUntil:limit:, but it probably should signal the
> run loop in some way that data is available on the X event queue and
> thus it is not necessary to enter poll/select (or enter it with a 0
> timeout just in order to check for data on other channels).