Re: Degenerate file access patterns

[Trevor]

I don't know enough to be very helpful, but I can report that on Ubuntu, I
also see  "992    5953   90234" from strace.

On Tue, Mar 21, 2017 at 10:33 AM Han-Wen Nienhuys <address@hidden> wrote:

> the repeating syscall is the read, on the same file descriptor. If
> fontconfig failed a cache, you'd more likely see
>
>  open() = 6
>  read(6, .. )
>  close(6)
>  open() = 6
>  read(6, .. )
>  close(6)
>
> I think.
>
> I'll have a look again tonight. Maybe I can attach a debugger (my
> machine has long lost the ability to compile lilypond. Sigh.)
>
> On Tue, Mar 21, 2017 at 5:00 AM, Werner LEMBERG <address@hidden> wrote:
> >
> >>> "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."
> >
> > Interesting, I don't get this behaviour on my openSuSE GNU/Linux box.
> >
> >> 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
> >
> > On my box this is
> >
> >   1       6      88
> >
> >> $ 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
> >
> > For me, it is again
> >
> >   1       6      88
> >
> >> Werner may have better hunches than I which code is really
> >> responsible for this.
> >
> > Maybe a problem with fontconfig?  Where is the location of
> > fontconfig's database of available fonts on your system?  This must be
> > created in advance so that lilypond can access it.  If it is missing,
> > fontconfig tries to build it (which makes e.g. the first invocation of
> > lilypond very slow on a Windows box since there is no global
> > fontconfig database).
> >
> > Is it possible that fontconfig always fails so that it tries again and
> > again?
> >
> >
> >     Werner
>
>
>
> --
> Han-Wen Nienhuys - address@hidden - http://www.xs4all.nl/~hanwen
>