Re: [BUG] Emacs UI dropping every 25th line, roughly

[Thomas Schwinge <thomas@schwinge.name>]

[-- Attachment #1: Type: text/plain, Size: 2841 bytes --]

Hallo!

On Sun, 30 Jan 2011 22:02:03 +0100, I wrote:
> That is, roughly every 25th line is dropped in the Emacs notmuch-search
> buffer!  (Via setting notmuch-command to a shell script, I intercepted
> the notmuch / emacs pipeline with tee, and found that what comes out of
> ``notmuch | tee'' is still sane, so I'm fairly sure it's an Emacs /
> notmuch elisp code issue.)
> 
> And, 25 times the medium length of a ``notmuch search [...]'' output line
> is... 4 KiB, the standard page size.  Is this ``just'' a problem in the
> notmuch elisp code, or is Emacs doing something awful with (wild
> speculation...) short reads on buffer page boundaries (or whatever else)?

I began to analyze this.  Here is a dump of my steps.

I used strace on the (already running) Emacs process.  strace would log
to several files: one for the main (Emacs) process, and a new one for
each forked process.  I can see that a ``notmuch search [...]'' process
is fork()ed / exec()uted.  It does a lot of read()ing from the DB, and
write()s out the results record by record (which in our case means line
by line).  Up to the point where I examined, there have been no short
writes.  The log:

    [some write()s for the first two dozen search results]
    16:26:54.143464 write(1, "thread:00000000000006c7   2009-12-16 [2/2] Thomas Schwinge; [subject] ([flags])\n", 135) = 135
    [...]
    16:26:54.266866 write(1, "thread:0000000000000ac4   2009-12-16 [1/1] jsm28@sourceware.org; [subject] ([flags])\n", 181) = 181

At this / in the middle of this point, the 4 KiB size is hit.  After
accumulating some more (notice the 3.6 seconds delay), Emacs read()s the
first chunk (line breaks inserted for clarity):

    16:26:57.928798 read(8, "[first two dozen results]"
                            "thread:00000000000006c7   2009-12-16 [2/2] Thomas Schwinge; [subject] ([flags])\n"
                            "t", 4096) = 4095

The last result line is obviously incomplete, only the `t' so far.

There is more to be read, so Emacs quickly goes on with the next chunk:

    16:26:57.966247 read(8, "hread:0000000000000ac4   2009-12-16 [1/1] jsm28@sourceware.org; [subject] ([flags])\n"
                            "[more results]", 4096) = 4095

That's the remainder of the partial line, plus further results.  This is
all fine.  It's now Emacs' job to re-assemble the two partial lines
(thread ac4).  I note that indeed this search result is missing in the
notmuch-search buffer.

(By the way, I wonder why read() returns 4095 bytes instead of 4096?)

I'll next move on to debugging what actually appears at the elisp layer.
I somehow don't think the Emacs core is faulty; probably rather our
asynchronous results presentation layer handles partial lines
incorrectly?  More to come later.


Grüße,
 Thomas

[-- Attachment #2: Type: application/pgp-signature, Size: 489 bytes --]