Re: Degenerate file access patterns

[Han-Wen Nienhuys]

After a intricate upgrade of laptop, I now have some stacktraces. They
don't tell me much,


read(16, "OTTO\0\r\0\200\0\3\0PCFF
\26g\353\377\0\0\r\30\0\0\366\253FFTM"..., 4096) = 4096
 > /usr/lib64/libc-2.24.so(__read_nocancel+0x7) [0xf7bd0]
 > /usr/lib64/libc-2.24.so(_IO_file_seekoff+0x34b) [0x7a4cb]
 > /usr/lib64/libc-2.24.so(fseek+0x79) [0x77999]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_Stream_Open+0x10d)
[0xc5fd]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_Stream_Seek+0x23)
[0xf253]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(TT_RunIns+0x20b09)
[0x43ed9]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(TT_RunIns+0x23c84)
[0x47054]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(TT_RunIns+0xd5ff)
[0x309cf]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_New_Size+0x263)
[0x128a3]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_Open_Face+0x4ad)
[0x1497d]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_New_Face+0x2b)
[0x1568b]
 > /home/hanwen/lilypond/usr/bin/lilypond(_ZStplIcSt11char_traitsIcESaIcEESbIT_T0_T1_EPKS3_RKS6_+0x1787cf)
[0x193b4f]


and


read(16, "OTTO\0\r\0\200\0\3\0PCFF
\26g\353\377\0\0\r\30\0\0\366\253FFTM"..., 4096) = 4096
 > /usr/lib64/libc-2.24.so(__read_nocancel+0x7) [0xf7bd0]
 > /usr/lib64/libc-2.24.so(_IO_file_underflow+0x140) [0x7c7e0]
 > /usr/lib64/libc-2.24.so(_IO_file_xsgetn+0x1c8) [0x7af98]
 > /usr/lib64/libc-2.24.so(fread+0x99) [0x6f5d9]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_Stream_ReadLong+0x40)
[0xf740]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(TT_RunIns+0x242ef)
[0x476bf]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_Get_X11_Font_Format+0x61b3)
[0x21243]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_New_Size+0x263)
[0x128a3]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_Open_Face+0x4ad)
[0x1497d]
 > /home/hanwen/lilypond/usr/lib/libfreetype.so.6.3.22(FT_New_Face+0x2b)
[0x1568b]
 > /home/hanwen/lilypond/usr/bin/lilypond(_ZStplIcSt11char_traitsIcESaIcEESbIT_T0_T1_EPKS3_RKS6_+0x1787cf)
[0x193b4f]
 > /home/hanwen/lilypond/usr/bin/lilypond(_ZNSt11char_traitsIcE2eqERKcS2_+0x1df13)
[0x1eb153]


if someone can build me a GUB binary without stripping debug symbols,
that would offer an avenue for debugging.


On Tue, Mar 21, 2017 at 1:21 AM, Han-Wen Nienhuys <address@hidden> wrote:
> On Thu, Mar 16, 2017 at 9:36 PM, Trevor <address@hidden> wrote:
>> I'm trying to run LilyPond in Google Cloud Functions
>> <https://cloud.google.com/functions/>, and execution is ridiculously slow
>> (like 40 seconds compilation vs. 2 seconds on my laptop). A Google Cloud
>> engineer tested it and reported the following:
>>
>> "The culprit is that the lilypond binary has a bit sub-optimal file access
>> pattern (opening the same file thousands of times and reading it byte by
>> byte, causing a syscall flood - nearly 500K lseek and read operations). On
>> a local machine, because of this issue, it will spend about 1s in I/O
>> syscalls, which is half of the total execution time. This currently does
>> not play nice with our systems, getting it from 1s to over half a minute."
>>
>> Anybody know why this behavior is exhibited? Is this something that might
>> be within the power of a programmer new to LilyPond development to fix?
>
> The font support is reading the same section of some font file over
> and over again.
>
> $ cat f.ly
> { c }
> $ strace -e trace=open,read lilypond f.ly  >& log ; grep OTTO log|wc
>     992    5953   90234
> $ grep OTTO log|head -10
> read(6, "OTTO\0\r\0\200\0\3\0PCFF
> \364\24\241\262\0\0\t\334\0\0\373PFFTM"..., 4096) = 4096
> read(6, "OTTO\0\r\0\200\0\3\0PCFF
> \364\24\241\262\0\0\t\334\0\0\373PFFTM"..., 4096) = 4096
> read(6, "OTTO\0\r\0\200\0\3\0PCFF
> \364\24\241\262\0\0\t\334\0\0\373PFFTM"..., 4096) = 4096
>
> the number of calls is apparently proportional to the number of glyphs
> in the file:
>
> $ cat f.ly
> \repeat unfold 100 { c }
>
> $ strace -e trace=open,read lilypond f.ly  >& log ; grep OTTO log|wc
> 40929  245575 3724501
>
> Werner may have better hunches than I which code is really responsible for 
> this.
>
>
> --
> Han-Wen Nienhuys - address@hidden - http://www.xs4all.nl/~hanwen



-- 
Han-Wen Nienhuys - address@hidden - http://www.xs4all.nl/~hanwen