Re: chromium port causing massive I/O faults

On Wed Jul 27 11, Gleb Kurtsou wrote:
> On (27/07/2011 00:48), Alexander Best wrote:
> > On Mon Jul 25 11, Matthias Andree wrote:
> > > Am 25.07.2011 09:21, schrieb Alexander Best:
> > > > On Mon Jul 25 11, Adrian Chadd wrote:
> > > >> Is it perhaps doing disk IO using mmap?
> > > > 
> > > > how can i check, whether that's the case or not?
> > > 
> > > Use truss(1) for instance.
> > > 
> > > However, unless there are *practical* problems, a high number of page
> > > faults is not an indication for problems.  Although it may sound scary,
> > > page faults are a feature of the memory management.
> > 
> > unfortunately truss(1) is crashing chromium :( i opened up a new thread
> > reagarding this issue on freebsd-current_at_.
> Could you try ktrace? It works for me
> 
> > another thing i noticed is the increase in system calls caused by chromium.
> > let's have a look at hub.freebsd.org:
> > 
> > uptime = 149 days
> > 
> > and 'vmstat -s' reports:
> > 
> > 2168697753 cpu context switches
> > 2266220366 device interrupts
> > 2902880931 software interrupts
> > 3779075897 traps
> > 902107847 system calls
> > 
> > now on my box:
> > 
> > uptime = 2 days
> > 
> > and 'vmstat -s' reports:
> > 
> > 1155995386 cpu context switches
> > 164577882 device interrupts
> > 189456976 software interrupts
> > 137007580 traps
> > 2178434582 system calls
> About 2.5k syscalls with chrome + a lot of other stuff running. 1.5k
> without chrome.
> 
> Looks like there is a lot of clock_gettime and gettimeofday syscalls.
> ~ % kdump -m 1 -f ktrace.out | grep 'CALL .*gettime' | wc -l
>    24343
> 
> ~ % kdump -E -m 1 -f ktrace.out | grep 'CALL .*gettime' | tail -20
>  12747 chrome   15.077376 CALL  gettimeofday(0x7fffff7f9630,0x7fffff7f9640)
>  12747 chrome   15.077396 CALL  clock_gettime(0x4,0x7fffffbfb6f0)
>  12747 chrome   15.077497 CALL  gettimeofday(0x7fffffbfb650,0x7fffffbfb660)
>  12747 chrome   15.077609 CALL  gettimeofday(0x7fffffbfb650,0x7fffffbfb660)
>  12747 chrome   15.077723 CALL  gettimeofday(0x7fffffbfb650,0)
>  12747 chrome   15.077845 CALL  clock_gettime(0,0x7fffffbfb2b0)
>  12747 chrome   15.078337 CALL  clock_gettime(0x4,0x7fffff9fa630)
>  12747 chrome   15.078544 CALL  clock_gettime(0x4,0x7fffff9fa650)
>  12747 chrome   15.078587 CALL  clock_gettime(0x4,0x7fffff9fa650)
>  12747 chrome   15.078632 CALL  clock_gettime(0x4,0x7fffff9fa650)
>  12747 chrome   15.078674 CALL  clock_gettime(0x4,0x7fffff9fa650)
>  12747 chrome   15.082803 CALL  gettimeofday(0x7ffffedd3630,0x7ffffedd3640)
>  12747 chrome   15.084644 CALL  gettimeofday(0x7fffffbfb650,0x7fffffbfb660)
>  12747 chrome   15.084746 CALL  clock_gettime(0x4,0x7fffffbfb670)
>  12747 chrome   15.084815 CALL  clock_gettime(0x4,0x7fffffbfb670)
>  12747 chrome   15.086620 CALL  gettimeofday(0x7ffffefd4650,0x7ffffefd4660)
>  12747 chrome   15.086736 CALL  clock_gettime(0x4,0x7ffffefd4670)
>  12747 chrome   15.086815 CALL  clock_gettime(0x4,0x7ffffefd4670)
>  12747 chrome   15.098315 CALL  gettimeofday(0x7fffffffafe0,0x7fffffffaff0)
>  12747 chrome   15.098680 CALL  clock_gettime(0x4,0x7fffffffb250)
> 
> Some work was done by kib_at_ to create a kernel page strong current time
> and other misc info to eliminate gettimeofday kind syscalls.  Bits of it
> were commited but I'm not sure if it was finished.
> But anyway calling gettimeofday hundreds of times per second is a chrome
> bug.

*lol* i did exactly the same measurements, you did. :) here are my results:

otaku% kdump|grep "CALL  mmap"|wc
     724    2896   58468
otaku% kdump -s|grep "CALL  clock_gettime"|wc
   49545  198180 2772674
otaku% kdump -s|grep "CALL  linux_clock_gettime"|wc
   40185  160740 2491298
otaku% kdump -s|grep "CALL  linux_gettimeofday"|wc 
   21670   86680 1278530
otaku% kdump -s|grep "CALL  gettimeofday"|wc 
    8173   32692  525053
otaku% kdump -s|grep "CALL  linux_sys_futex"|wc
    6191   24764  548800

cheers.
alex

> 
> FreeBSD 9.0-CURRENT #2 r224003+777e962: Thu Jul 14 13:04:55 EEST 2011
> chromium-11.0.696.57_1
> 
> > i ran the following command twice. first time without running chromium and the
> > second time with chromium running:
> > 
> > otaku% vmstat -s|grep "system calls"; sleep 1; vmstat -s|grep "system calls"
> > 2178187850 system calls
> > 2178189739 system calls
> > 
> > otaku% vmstat -s|grep "system calls"; sleep 1; vmstat -s|grep "system calls"
> > 2177998835 system calls
> > 2178022003 system calls
> > 
> > so it's 2k/sec vs. 23k/sec!!!!
> > 
> > cheers.
> > alex