iLiad The hidden cost of erdm and dmQFull

[scotty1024]

I'm planning the replacement of liberdm so I've been sniffing around the displayMgr to see how it works. (it was also handy in figuring out erdm to get x48/mrxvt working nicely)

Primer on understanding the strace output below.

Each line is a call into the Linux kernel.

The numbers at the end of each line in <>'s are the time in microseconds (1/1000000 of a second) to execute the kernel call.

A "recvfrom(4, "!0,3,0"" is a dmQFull and a "recvfrom(4, "!0,3,2"" is a dmQTyping.

We start with a simple page flip in the version 5 ipdf.

root@ereader:~# strace -p 279 -T
Process 279 attached - interrupt to quit
recvfrom(4, "!0,3,2", 1024, 0, {sa_family=AF_INET, sin_port=htons(1035), sin_addr=inet_addr("127.0.0.1")}, [16]) = 6 <5.043367>
gettimeofday({1163451396, 377505}, NULL) = 0 <0.000257>
gettimeofday({1163451396, 384705}, NULL) = 0 <0.000258>
select(5, [4], NULL, NULL, {0, 0})      = 0 (Timeout) <0.000307>
gettimeofday({1163451396, 398153}, NULL) = 0 <0.000260>
ioctl(3, EXT2_IOC_GETVERSION or VIDIOCGCAP, 0xbffff020) = 0 <0.504241>
gettimeofday({1163451396, 953536}, NULL) = 0 <0.002771>
nanosleep({1, 0}, NULL)                 = 0 <1.003448>

The important numbers above are:
gettimeofday({1163451396, 398153}, NULL) = 0 <0.000260>
gettimeofday({1163451396, 953536}, NULL) = 0 <0.002771>
nanosleep({1, 0}, NULL) = 0 <1.003448>

Before the ioctl call to re-ink the display a gettimeofday call takes 260us. After the ioctl call it takes 2771us, roughly 10 times longer.

Since we're just dmQTyping I can back to back very quickly...

recvfrom(4, "!0,3,2", 1024, 0, {sa_family=AF_INET, sin_port=htons(1035), sin_addr=inet_addr("127.0.0.1")}, [16]) = 6 <0.000314>
gettimeofday({1163451477, 673222}, NULL) = 0 <0.000251>
gettimeofday({1163451477, 674260}, NULL) = 0 <0.000250>
select(5, [4], NULL, NULL, {0, 0})      = 0 (Timeout) <0.000303>
gettimeofday({1163451477, 676585}, NULL) = 0 <0.000251>
ioctl(3, EXT2_IOC_GETVERSION or VIDIOCGCAP, 0xbffff020) = 0 <0.599398>
gettimeofday({1163451478, 303560}, NULL) = 0 <0.002788>
nanosleep({1, 0}, NULL)                 = 0 <1.003638>

Notice how that recvfrom is now only 314us, ipdf v5 already had another page flip request loaded and waiting. (that's my boy!)

You'll notice the same pattern, fast gettimeofday's, then slow gettimeofday after the ioctl.

recvfrom(4, "!0,3,2", 1024, 0, {sa_family=AF_INET, sin_port=htons(1035), sin_addr=inet_addr("127.0.0.1")}, [16]) = 6 <0.000313>
gettimeofday({1163451479, 313202}, NULL) = 0 <0.000251>
gettimeofday({1163451479, 314239}, NULL) = 0 <0.000251>
select(5, [4], NULL, NULL, {0, 0})      = 0 (Timeout) <0.000303>
gettimeofday({1163451479, 316566}, NULL) = 0 <0.000251>
ioctl(3, EXT2_IOC_GETVERSION or VIDIOCGCAP, 0xbffff020) = 0 <0.658336>
gettimeofday({1163451480, 33553}, NULL) = 0 <0.002803>
nanosleep({1, 0}, NULL)                 = 0 <1.003526>

One more back to back, that's roughly 1 second or so per page... ipdf is now out running the 1 second hard coded limit imposed by displayMgr with that nanosleep call.

recvfrom(4, "!0,3,0", 1024, 0, {sa_family=AF_INET, sin_port=htons(1027), sin_addr=inet_addr("127.0.0.1")}, [16]) = 6 <208.695630>
gettimeofday({1163451689, 738402}, NULL) = 0 <0.000251>
gettimeofday({1163451689, 739440}, NULL) = 0 <0.000252>
select(5, [4], NULL, NULL, {0, 0})      = 0 (Timeout) <0.002863>
gettimeofday({1163451689, 750937}, NULL) = 0 <0.000245>
ioctl(3, EXT2_IOC_GETVERSION or VIDIOCGCAP, 0xbffff020) = 0 <0.500769>
gettimeofday({1163451690, 265128}, NULL) = 0 <0.002852>
nanosleep({1, 0}, NULL)                 = 0 <1.011523>

OK the above is me pressing quit and a dmQFull being issued.

The important number here is:
nanosleep({1, 0}, NULL) = 0 <1.011523>

Notice how that nano sleep took 8ms longer? The CPU is still running slowly after 1 second!

recvfrom(4, "!0,3,0", 1024, 0, {sa_family=AF_INET, sin_port=htons(1027), sin_addr=inet_addr("127.0.0.1")}, [16]) = 6 <0.002850>
gettimeofday({1163451691, 293314}, NULL) = 0 <0.002797>
gettimeofday({1163451691, 299442}, NULL) = 0 <0.002775>
select(5, [4], NULL, NULL, {0, 0})      = 0 (Timeout) <0.002855>
gettimeofday({1163451691, 312888}, NULL) = 0 <0.003286>
ioctl(3, EXT2_IOC_GETVERSION or VIDIOCGCAP, 0xbffff020) = 0 <0.838383>
gettimeofday({1163451692, 161289}, NULL) = 0 <0.003292>
nanosleep({1, 0}, NULL)                 = 0 <1.005671>

The above was a back-to-back dmQFull (need to optimize that out of ipdf) notice how all the kernel calls are running slowly. The CPU is still in slow down mode as the screen is still being re-inked.

During the black flash the CPU is hobbled and not able to execute at full speed, most likely because the iLiad's hardware is grabbing main memory access away from the CPU to get the bits to put up on the e-Ink panel.

With dmQTyping ipdf v5 is out running erdm, pages could be put up faster but erdm is slowing it down due to the 1 second time out built into it. Also, dmQTyping is allowing the CPU to get back to full performance and begin rendering the next PDF page ASAP.

Part of the reason I was seeing such poor Poppler performance was the black flash hobbling Poppler.

write(2, "PDFDoc::displayPage uses 2115148"..., 33) = 33
gettimeofday({1163454380, 722190}, NULL) = 0
write(2, "xMgr::createImage uses 2970\n", 28) = 28

The above rendering times are from v5, they are 520ms faster than v4 timings.

I think all of this adds up to explain the power savings I'm seeing. The CPU has to run longer since it is being slowed down by a dmQFull. The dmQFull is spending more time inking the display, with that expensive 30V power supply turned on to run the electrophoresis.

Version 6 of ipdf will by-pass erdm and invoke the ioctl directly. We'll see how fast pages can flip then!

[Antartica]

Originally Posted by scotty1024

I'm planning the replacement of liberdm so I've been sniffing around the displayMgr to see how it works. (it was also handy in figuring out erdm to get x48/mrxvt working nicely)

Great detective work, Scotty! :-D

[arivero]

Originally Posted by scotty1024

30V power supply turned on to run the electrophoresis.

Hmm?? 30 Volts power supply there? So one can not to turn the page with 5 volts? Damn, now I know why I failed to paint in my spare display.