Obscure timing issue

[Wolfgang Lux]

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).

Wolfgang