Re: chromium port causing massive I/O faults

From: Gleb Kurtsou <gleb.kurtsou_at_gmail.com>
Date: Wed, 27 Jul 2011 11:33:39 +0300
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.

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
Received on Wed Jul 27 2011 - 06:35:02 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:16 UTC