gettimeofday calls under Redhat ES 4 Update 2

[Ollie Cook]

Hi,

Since upgrading from Redhat ES 4 Update 1 to Redhat ES 4 Update 2 we
have been seeing our java processes making a great deal of gettimeofday
system calls which they didn't previously make.

The following list demonstrate the change in behaviour. It shows the
number of system calls (from strace) over a short (5-10 second) period
of one Java thread.

We are running 1.4.2-02 (but we have reproduced the behaviour on -03 as
well) using the 64-bit AMD binary.

  2 close
  6 open
  8 fstat
 10 stat
 71 read
105 ioctl
122 lseek
215 sched_yield
344 poll
926 write
   1287 sendto
   1354 rt_sigprocmask
   1354 rt_sigsuspend
   1356 rt_sigreturn
   2230 recvfrom
  14690 kill
 812536 gettimeofday

As you can see gettimeofday is by far and away the most frequently
called system call under Update 2. The following is a similar sample
from Update 1 (although for a shorter time period):

  1 sched_yield
  2 open
  2 stat
 19 poll
 37 write
 66 rt_sigprocmask
 66 rt_sigsuspend
 86 sendto
 88 rt_sigreturn
143 recvfrom
792 kill

I'm following this up with Redhat in case it's related to a modification
to glibc or libpthread, and have no reason to believe this issue is
necessarily related to the Blackdown JVM itself.

However, I would be keen to hear if any other users of the Blackdown JVM
have noticed similar behaviour to this on Redhat ES 4 Update 2.

Yours,

Ollie
-- 
Ollie Cook
UNIX Scripter
Information Systems

Direct Line: 020 8834 8128
Waterfront | Hammersmith Embankment | Chancellors Road London | W6 9HP


--
To UNSUBSCRIBE, email to [EMAIL PROTECTED]
with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]

Re: gettimeofday calls under Redhat ES 4 Update 2

[Ollie Cook]

On Tue, 2006-02-07 at 13:34 -0500, Dominic Duval wrote:
> Hi,
> 
> Have you tried running the whole thing through lstrace? That might help
> determining which function in glibc causes the call to gettimeofday(). 
> 
> If you have access to a test system, you might also want to downgrade
> glibc to whatever version we used in U1, just to make sure the problem
> comes from glibc (which is what I suspect).
> 
> Let us know if you find the solution.
> 
> Cheers,
>   -Dominic

Hi,

I have been able to reproduce this with a simple test script (attached).

ltrace[1] demonstraces the change in system call activity. I have
included only the top 5 in each list for brevity:

Under RHES4.1:

 46 SYS_stat
 55 SYS_futex
 58 SYS_lstat
 76 SYS_open
105 SYS_mmap

Under RHES4.2:

 54 SYS_futex
 58 SYS_lstat
 76 SYS_open
105 SYS_mmap
   1658 SYS_gettimeofday

Over 1500 calls to gettimeofday, out of thin air.

We've not yet tried a downgrade of glibc on the affected systems, but
that is out next test.

As this is clearly not a problem related to the Blackdown JVM itself,
this shall be my last email to the list on the subject. If any reader is
also affected by this problem and would be interested in updates, by all
means make yourself known to me privately.

Ollie

1: ltrace -S /usr/java/j2sdk1.4.2_02_bd/bin/java BFThreadTest 2>&1|awk
-F\( '{print $1}'|sort|uniq -c | sort -n | tail -5
// BFThreadTest
//
// Simple class to demonstrate that creation of threads
// under Redhat ES 4 Update 2 produces spurious calls
// to SYS_gettimeofday, which are not present when
// running the same code on Redhat ES 4 Update 1.
//
// Tested with Blackdown JVM v1.4.2-02 and Sun JVM
// v1.4.2-08.
//
// (c) Betfair Limited 2006
//
// Ollie Cook <[EMAIL PROTECTED]>

public class BFThreadTest extends Thread {
	private int countDown = 50;

	public BFThreadTest() {
		super("BFThreadTest");
		start();
	}

	public void run() {
		do {
		  countDown--;
		} while (countDown > 0);

		return;
	}

	public static void main(String[] args) {
		for(int i = 0; i < 1; i++) {
			new BFThreadTest();
		}
	}
}