Using strace with Java

As with native applications, using strace with Java will give you some visibility into how your Java application is stressing the kernel. The challenge to using strace is to run it on the java executable, not on the java launch script. We do this with a modest trick— using the debugger backdoor built into the java launch script.

Synopsis:

DEBUG_PROG="strace <options>" java -green ...

Setting the debug_prog environment variable causes the java launch script to invoke the java executable with the specified command. The -green flag is needed because strace is (at present) confused by native-threaded programs.

Example:

Listings 63.3 and 63.4 show the results of running the example program with strace. In Listing 63.4, CPU usage is much lower, particularly for the read and write system calls.

Listing 63.3 Running strace on the First Invocation of Printx bash$ DEBUG_PROG="strace -c" java -green PrintX 100000 0 >/dev/null execve("/usr/local/Java/jdk1.2/bin/i386/native threads/java", ["/usr/local bash$ DEBUG_PROG="strace -c" java -green PrintX 100000 0 >/dev/null execve("/usr/local/Java/jdk1.2/bin/i386/native threads/java", ["/usr/local

/Java/jdk1.

2/bin/i38

36/native threads/java",

"Hello", "100000",

"0"

[/* 3

3 vars

*/])

= 0

% time

seconds

usecs/call

calls

errors syscall

78.

70

1.

870720

19

100005

write

19.

82

0.

471126

1098

429

read

0

.47

0

.011254

110

102

kill

0

.21

0

.005023

27

189

brk

0

.15

0

.003659

8

438

llseek

0

.14

0

.003342

47

71

30 open

0

.13

0

.003085

23

132

lstat

0

.10

0

.002264

162

14

14 SYS 179

0

.07

0

.001751

55

32

4 stat

0

.06

0

.001404

28

51

mmap

0

.03

0

.000796

36

22

mprotect

0

.02

0

.000497

16

32

close

0

.02

0

.000367

9

43

fstat

0

.01

0

.000332

17

19

gettimeofday

0

.01

0

.000325

36

9

munmap

0.

01

0.

000325

23

14

l4 sigreturn

0.

01

0.

000180

30

6

readlink

0.

01

0.

000145

6

24

SYS l75

0.

00

0.

000109

7

15

SYS l74

0.

00

0.

000071

71

1

socket

0.

00

0.

000064

32

2

l connect

0.

00

0.

000061

61

1

clone

0.

00

0.

000045

45

1

pipe

0.

00

0.

000029

15

2

uname

0.

00

0.

000024

8

3

fcntl

0.

00

0.

000020

5

4

getpid

0.

00

0.

000018

9

2

lseek

0.

00

0.

000014

7

2

getrlimit

0.

00

0.

000011

6

2

time

0.

00

0.

000011

6

2

setrlimit

0.

00

0.

000011

6

2

getdents

0.

00

0.

000009

9

1

wait4

0.

00

0.

000008

8

1

personality

0.

00

0.

000007

7

1

times

0.

00

0.

000006

6

1

getuid

100.00 2.377113 101675 63 total

Listing 63.4 Running strace on the second invocation of Printx bash$ DEBUG_PROG="strace -c" java -green PrintX 0 100000 >/dev/null execve("/usr/local/Java/jdk1.2/bin/i3 8 6/native threads/java", ["/usr/local

/Java/jdk1.2/bin/i386/native_threads/java", "Hello", "0", "100000"], [/* 3 3 vars */]) = 0

% time seconds usecs/call calls errors syscall

38.68 0.024711 58

25.20 0.016099 125

6.86 0.004382 23

5.84 0.003731 9

4.66 0.002979 42

4.32 0.002760 21

3.11 0.001987 153

2.53 0.001617 51

1.99 0.001273 25

1.46 0.000935 52

0.73 0.000464 15

0.64 0.000410 19

0.63 0.000405 18

0.60 0.000383 17

0.56 0.000356 8

0.50 0.000321 36

0.40 0.000257 86

0.27 0.000171 29

0.17 0.000108 7

429 read

129 kill

189 brk

438 _llseek

71 30 open

132 lstat

13 13 SYS_17 9

32 4 stat

51 mmap

18 write

32 close

22 mprotect

23 gettimeofday 23 SYS_175

43 fstat

9 munmap

3 fcntl

6 readlink

15 SYS 174

0.

16

0.

000101

8

13

13

sigreturn

0.

10

0.

000067

34

2

getdents

0.

10

0.

000063

32

2

1

connect

0.

10

0.

000061

61

1

clone

0.

, 09

0.

000059

59

1

socket

0.

08

0.

,000054

54

1

pipe

0.

05

0.

000029

15

2

uname

0.

03

0.

000019

5

4

getpid

0.

03

0.

000018

9

2

lseek

0.

, 02

0.

000014

7

2

getrlimit

0.

, 02

0.

000011

6

2

time

0.

02

0.

000011

6

2

setrlimit

0.

01

0.

000008

8

1

wait4

0.

01

0.

000008

8

1

personality

0.

01

0.

000007

7

1

times

0.

01

0.

000006

6

1

getuid

100.00 0.063885 1716 61 total

100.00 0.063885 1716 61 total

What a difference! The first invocation of the program spent 1.87 seconds performing writes—the write system call was invoked 100,000 times. The second invocation only called write 18 times and consumed drastically less kernel time. The cause of the performance differences is now obvious: the java.io.PrintWriter class is buffering its output, whereas the java.io.Printstream class is not.

This is the sort of detail we can only learn from a trace of kernel activities.

Continue reading here: Profiler A Native Application Profiler

Was this article helpful?

+1 0