Re: Degenerate file access patterns

[Trevor]

Downloaded binary.

On Thu, Mar 23, 2017 at 2:38 PM Han-Wen Nienhuys <address@hidden> wrote:

> Trevor, did you compile it from scratch or are you using the packaged
> binary?
>
>
> On Thu, Mar 23, 2017 at 11:42 AM, Trevor <address@hidden> wrote:
> > 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
>
>
>
> --
> Han-Wen Nienhuys - address@hidden - http://www.xs4all.nl/~hanwen
>