Re: benchmark result

[Mathieu Lacage <Mathieu dot Lacage at sophia dot inria dot fr>]

Well, I am a bit stubborn and I must say I was very disapointed by the
performance of the code generated by gcj so, I started looking into what
are the bottlenecks:

1) I did run my simulation code built with gcc 3.4.3. The same setup as
previously reported in this email was used. Interestingly, I also used a
new patch which decreased the amount of short-lived objects created by
the code at the cost of creating a long-lived pool of maximum number
possible of these short-lived objects. Although this code had little to
no influence (except on really large simulations) on the simulation time
when it ran on sun's jdk 1.4.2 (at best, a 5% improvement). This new
patch did have an immediate effect on the simulation run time when
compiled with gcc 3.4.3 and 4.0.0 (a ~10% improvement even on really
short simulations). This experiment led me to believe there was probably
a major bottleneck in the GC used by gcj. So, I decided to do a bit of
system-level profiling with oprofile.

2) opreport first reported:
Profiling through timer interrupt
          TIMER:0|
  samples|      %|
------------------
    75829 84.9767 vmlinux
     6506  7.2909 libgcj.so.5.0.0
     2767  3.1008 MainSimulation
...

Which seemed to imply that the overall simulation time was spent in the
libgcj and MainSimulation binaries. Obviously, I did not expect that
much time to be spent in libgcj so, I decided to look into a profile
specific to that binary.

3) Thus, I ran: 
[mlacage@chronos treegrowth]$ opgprof /opt/gcc-3.4.3/lib/libgcj.so
[mlacage@chronos treegrowth]$ gprof /opt/gcc-3.4.3/lib/libgcj.so -p gmon.out
Flat profile:
 
Each sample counts as 1 samples.
  %   cumulative   self              self     total
 time   samples   samples    calls  T1/call  T1/call  name
 22.35   1454.00  1454.00                             _ieee754_log
 12.87   2291.00   837.00                             GC_mark_from
 10.19   2954.00   663.00                             Jv_LookupInterfaceMethodIdx
  7.79   3461.00   507.00                             ZN4java4util9ArrayList3getEi
  4.98   3785.00   324.00                             Z20_Jv_IsAssignableFromPN4java4lang5ClassES2_
  4.92   4105.00   320.00                             Jv_CheckCast
  4.33   4387.00   282.00                             frame_dummy
  3.37   4606.00   219.00                             ZN4java4util14AbstractList$17hasNextEv
  3.30   4821.00   215.00                             ZN4java4util14AbstractList$18checkModEv
  3.01   5017.00   196.00                             GC_local_gcj_malloc
  2.47   5178.00   161.00                             ZN4java4util14AbstractList$14nextEv
  2.34   5330.00   152.00                             ZN4java4util9ArrayList3addEPNS_4lang6ObjectE
  2.08   5465.00   135.00                             ZN4java4util9ArrayList19checkBoundExclusiveEi
  1.48   5561.00    96.00                             Jv_AllocObjectNoFinalizer
  1.48   5657.00    96.00                             Jv_CheckArrayStore
  1.38   5747.00    90.00                             init
  1.14   5821.00    74.00                             ZN4java4lang4Math3logEd
  1.08   5891.00    70.00                             ZN4java4util12AbstractList8iteratorEv

Ok, so, my application does a lot of calls to the log function, no
surprise here. Now, I expected the GC to be pretty high here and, well,
it seems to be with GC_mark_from. However, I must say I am pretty
surprised to see Jv_LookupInterfaceMethodIdx which I don't know anything
about.

Could someone tell me what this function really does ? Is it expected to
be so high into an application profile ? If not, what could I do to
reduce its usage ?

regards,
Mathieu

On Thu, 2004-12-02 at 15:14 +0100, Mathieu Lacage wrote: 
> hi,
> 
> Here are some benchmark results of gcc-3.4.3m gcc cvs HEAD from
> yesterday and the sun jdk 1.4.2_04. The test application is a stochastic
> simulator which is mostly CPU-bound and which was used such that its
> random generators were always initialized with the same seed.
> 
> All measurements were consistent +/- 0.1 across multiple runs. gcc
> itself was built with the default configure options. The application was
> built with -O2 -Wall -gdwarf-2. If you need more information or other
> test runs, please, let me know.
> 
> application build time:
> 3.4.3: 
> 	real: 12.25
> 	user: 5.87
> 	sys: 1.53
> 4.0.0: 
> 	real: 14.80
> 	user: 7.90
> 	sys: 1.97
> 
> application run time:
> gcc 3.4.3:
> 	real: 10.46
> 	user: 10.36
> 	sys: 0.04
> gcc 4.0.0:
> 	real: 11.57
> 	user: 11.42
> 	sys: 0.04
> jdk 1.4.2 (--server):
> 	real: 7.45
> 	user: 7.26
> 	sys: 0.10
> 
> regards,
> Mathieu
--