FULL PRODUCT VERSION :
java version "1.6.0_16"
Java(TM) SE Runtime Environment (build 1.6.0_16-b01)
Java HotSpot(TM) Server VM (build 14.2-b01, mixed mode)

FULL OS VERSION :
Linux 2.6.18-128.2.1.el5PAE #1 SMP Tue Jul 14 07:15:01 EDT 2009 i686 i686 i386 GNU/Linux

A DESCRIPTION OF THE PROBLEM :
I am trying to profile a monte carlo simulation (see attached source code).
When I run the code, 3 things tell me that the majority of my time is spent in the method StrictMath.log:
1) My profiler (YourKit)
2) hprof (log attached)
3) Taking periodic stack dumps shows the main thread always in the method
  Total test time is about 11 seconds on my machine for 100,000,000 iterations.

At this stage, I replace the variable definition "DOLOG = true" with "DOLOG = false" in the source code and re-run the test. The test time goes down to 7 seconds, which means that the VM was actually spending about 35% of its time in StrictMath.log.

Why the discrepancy? Is stack information somehow getting "stuck" on entry/exit of a native method?

Note that with the client VM I notice the same phenomenon, but with StrictMath.sqrt method.

THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: Yes

THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Yes

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
1. Run the given code with as java -agentlib:hprof=sampling,file=sampling.txt tests.ProfilerTest
2. Run the same code as java tests.ProfilerTest > stacks.txt and take 20 random stack traces by sending kill -QUIT to the process 20 times
3. Change the line "private static final boolean DOLOG = true;" to "private static final boolean DOLOG = false;"
4. Recompile and run as java tests.ProfilerTest

EXPECTED VERSUS ACTUAL BEHAVIOR :
Expected results:
Removing the call to StrictMath.log should reduce the execution time by the percentage shown in profiling snapshot. The random stack traces should correspond more or less to the percentage times in the snapshot.

Actual results:
File sampling.txt shows almost 100% of CPU time spent in method StrictMath.log, but removing this call by setting DOLOG to false reduces execution time from 11 seconds to 7 seconds, a saving of approximately 35%. Therefore we should expect the profiler to show CPU time of 30-40% in this method.
Also, looking at the random stack traces, they almost all have StrictMath.log as their final frame - since it is a random sampling we would only expect to have one in three stack frames here.
REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
package tests;

import java.util.Random;

public class ProfilerTest extends Random {
private static final long multiplier = 0x5DEECE66DL;
private static final long addend = 0xBL;
private static final long mask = (1L << 48) - 1;
private static final boolean DOGAUSSIAN = true;
private static final boolean DORANDOMDOUBLE = true;
private static final boolean DOLOG = true;

public static void main (String[] args) {
long t0 = System.currentTimeMillis ();
new ProfilerTest ().doIt ();
System.out.println ("DOGAUSSIAN = " + DOGAUSSIAN);
System.out.println ("DORANDOMDOUBLE = " + DORANDOMDOUBLE);
System.out.println ("DOLOG = " + DOLOG);
System.out.println ("Time elapsed = " + (System.currentTimeMillis () - t0) / 1000);
}

private double doIt () {
double total = 0.0;
for (int ii = 0; ii < 100000000; ii++) {
total += nextGaussian ();
}

return total;
}

private boolean haveNextNextGaussian = false;
private double nextNextGaussian;

@Override
public synchronized double nextGaussian () {
if (DOGAUSSIAN) {
// See Knuth, ACP, Section 3.4.1 Algorithm C.
if (haveNextNextGaussian) {
haveNextNextGaussian = false;
return nextNextGaussian;
} else {
double v1, v2, s;
do {
v1 = 2 * nextDouble() - 1; // between -1 and 1
v2 = 2 * nextDouble() - 1; // between -1 and 1
s = v1 * v1 + v2 * v2;
} while (s >= 1 || s == 0);
double multiplier = StrictMath.sqrt(-2 * doLog (s) /s);
nextNextGaussian = v2 * multiplier;
haveNextNextGaussian = true;
return v1 * multiplier;
}
} else {
return 0.3;
}
}

private double doLog (double s) {
if (DOLOG) {
return StrictMath.log (s);
} else {
return 0.5;
}
}

@Override
public double nextDouble() {
if (DORANDOMDOUBLE) {
long l = ((long)(next(26)) << 27) + next(27);
return l / (double)(1L << 53);
} else {
return 0.3456;
}
}

private long seed = 0;

@Override
protected int next (int bits)
{
seed = (seed * multiplier + addend) & mask;
return (int)(seed >>> (48 - bits));

}
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
None found.