String initialization and performance

Question

This is a performance related question:

In the repeatPrint1() method, I initialized some String attributes to null before using them in a loop. In the repeatPrint2() method, I initialized some String attributes directly inside the loop.

When I tested, the result was amazing - repeatPrint2() was performing better than repeatPrint1() up to almost 2500 records, but after that repeatPrint1() started performing better than repeatPrint2().

Can anyone explain why this happened? In a code review, what can we take as the correct way?

Code Snippet:

public static void main(String[] args) throws Exception {    
    long startTime1 = System.nanoTime();    
    repeatPrint1();
    long estimatedTime1 = System.nanoTime() - startTime1;
    long startTime2 = System.nanoTime();
    repeatPrint2();
    long estimatedTime2 = System.nanoTime() - startTime2;
    System.out.println("estimatedTime1: " + estimatedTime1);
    System.out.println("estimatedTime2: " + estimatedTime2);
}


private static void repeatPrint1() {
    String name1 = null;
    String name2 = null;
    String name3 = null;
    String name4 = null;
    String name5 = null;

    for(int x = 10; x < 2500; x = x + 1) {        
        name1 = "My Name is AAAA" + x;
        name2 = "My Name is BBBB" + x;
        name3 = "My Name is CCCC" + x;
        name4 = "My Name is DDDD" + x;
        name5 = "My Name is EEEE" + x;

        System.out.print("name1 : " + name1);
        System.out.print("name2 : " + name2);
        System.out.print("name3 : " + name3);
        System.out.print("name4 : " + name4);
        System.out.print("name5 : " + name5);

        System.out.println("value of x : " + x);         
    }     
}


private static void repeatPrint2() {     
    for(int x = 10; x < 2500; x = x + 1) {        
        String Sname1 = "My Name is AAAA" + x;
        String Sname2 = "My Name is BBBB" + x;
        String Sname3 = "My Name is CCCC" + x;
        String Sname4 = "My Name is DDDD" + x;
        String Sname5 = "My Name is EEEE" + x;

        System.out.print("Sname1 : " + Sname1 );
        System.out.print("Sname2 : " + Sname2 );
        System.out.print("Sname3 : " + Sname3 );
        System.out.print("Sname4 : " + Sname4 );
        System.out.print("Sname5 : " + Sname5 );

        System.out.println("value of x : " + x );        
    }     
}

Try testing `repeatPrint2` before `repeatPrint1`.. You might get different results. :) — MAV, Aug 30 '14 at 10:14
Can you discuss your test environment, i.e. machine, load and number of runs? — Manu, Aug 30 '14 at 10:15

score 3 · Answer 1 · edited May 23 '17 at 10:25

3

Have a look at this question, which describes how to setup a good microbenchmark.

Two important points are:

Have a warmup phase where you call your methods for some ten thousand times.
This way the JIT will cache the method.
There will be a difference if you call repeatPrint1() before repeatPrint2() and vice versa

The results you are getting with your code will differ at any run. Spend some time to setup a good benchmark to have valueable results.

edited May 23 '17 at 10:25

Community

1
1

answered Aug 30 '14 at 10:16

Steve Benett

12,843
7
59
79

repeatPrint1() looks good when I tested individually.With 500 records , repeatPrint1() took 63869468 nanoseconds, but repeatPrint2() took 77103800 nanoseconds. So it behaves differently when we test individually and together as I mentioned. Actually i want to know how JVM interpret in 2 cases. – user3924979 Aug 30 '14 at 10:23
Well, in relation to what? – Steve Benett Aug 30 '14 at 10:24

score 3 · Answer 2 · answered Aug 30 '14 at 10:16

Read the byte code using javap and compare the two method transformation.

From the code you posted, I think it will be pretty much the same: the compiler should move the local variable (as in repeatPrint2) to the top of method.

What you encountered is probably the JIT compiler kick in and optimizing your code on the fly.

And I would personally prefer declaring variable in the scope it's used rather than in the outer scope (eg: like repeatPrint2): this is better for readability and for refactoring.

Chris K · Answer 3 · 2014-08-30T11:04:10.267

The two approaches that you have given are basically identical. Your timings are being thrown off primarily because the JVM has not warmed up; hotspot does not kick in until a method or loop has been repeated over 10,000 times. After that many repetitions you can often also have GC kicking in adhoc, as well as OS processes in the mix too.

To address some of these problems in a benchmark, warm up each method over 10k times and repeat several times. For OS noise, be sure to shutdown as many other apps and processes as you can and make sure that the machine is running idle. The OS can of course be tuned too, but lets leave that as off topic for now. Below is some example code that will give you an idea, I have also added two more ways to optimise the loop; just for fun ;)

I include the timings that I got towards the bottom. The things to note are

the two approaches that you included start off varying, but normalise to being about the same pretty quickly
the cost of your code is being dwarfed by calls to System.out; in otherwords the io itself. to demonstrate that I have given two other alternatives, one that makes more calls to System.out and another that makes less.

estimatedTime1: 17.27938 ms

estimatedTime2: 17.45852 ms

estimatedTime3: 100.61994 ms

estimatedTime4: 9.553329999999999 ms

public class Foo {
    public static void main( String[] args ) throws Exception {
        time1();
        time2();
        time3();
        time4();

        time1();
        time2();
        time3();
        time4();

        time1();
        time2();
        time3();
        time4();
    }

    private static final int REPEAT = 100;

    private static void time1() {
        long startTime1 = System.nanoTime();
        for ( int i=0; i<REPEAT; i++ ) {
            repeatPrint1();
        }
        long estimatedTime1 = System.nanoTime() - startTime1;

        double dur = estimatedTime1/1000000.0/REPEAT;
        System.out.println( "estimatedTime1: " + dur );
    }

    private static void time2() {
        long startTime1 = System.nanoTime();
        for ( int i=0; i<REPEAT; i++ ) {
            repeatPrint2();
        }
        long estimatedTime1 = System.nanoTime() - startTime1;

        double dur = estimatedTime1/1000000.0/REPEAT;
        System.out.println( "estimatedTime2: " + dur );
    }

    private static void time3() {
        long startTime1 = System.nanoTime();
        for ( int i=0; i<REPEAT; i++ ) {
            repeatPrint3();
        }
        long estimatedTime1 = System.nanoTime() - startTime1;

        double dur = estimatedTime1/1000000.0/REPEAT;
        System.out.println( "estimatedTime3: " + dur );
    }

    private static void time4() {
        long startTime1 = System.nanoTime();
        for ( int i=0; i<REPEAT; i++ ) {
            repeatPrint4();
        }
        long estimatedTime1 = System.nanoTime() - startTime1;

        double dur = estimatedTime1/1000000.0/REPEAT;
        System.out.println( "estimatedTime4: " + dur );
    }



    private static void repeatPrint1() {

        String name1 = null;
        String name2 = null;
        String name3 = null;
        String name4 = null;
        String name5 = null;
        for ( int x = 10; x < 2500; x = x + 1 ) {

            name1 = "My Name is AAAA" + x;
            name2 = "My Name is BBBB" + x;
            name3 = "My Name is CCCC" + x;
            name4 = "My Name is DDDD" + x;
            name5 = "My Name is EEEE" + x;

            System.out.print( "name1 : " + name1 );
            System.out.print( "name2 : " + name2 );
            System.out.print( "name3 : " + name3 );
            System.out.print( "name4 : " + name4 );
            System.out.print( "name5 : " + name5 );

            System.out.println( "value of x : " + x );

        }

    }


    private static void repeatPrint2() {

        for ( int x = 10; x < 2500; x = x + 1 ) {

            String Sname1 = "My Name is AAAA" + x;
            String Sname2 = "My Name is BBBB" + x;
            String Sname3 = "My Name is CCCC" + x;
            String Sname4 = "My Name is DDDD" + x;
            String Sname5 = "My Name is EEEE" + x;

            System.out.print( "Sname1 : " + Sname1 );
            System.out.print( "Sname2 : " + Sname2 );
            System.out.print( "Sname3 : " + Sname3 );
            System.out.print( "Sname4 : " + Sname4 );
            System.out.print( "Sname5 : " + Sname5 );

            System.out.println( "value of x : " + x );

        }
    }



    private static void repeatPrint3() {
        for ( int x = 10; x < 2500; x = x + 1 ) {
            pr1( 1, x, "AAAA" );
            pr1( 2, x, "BBBB" );
            pr1( 3, x, "CCCC" );
            pr1( 4, x, "DDDD" );
            pr1( 5, x, "EEEE" );
            xr1( x );
        }
    }
    private static void pr1( int i, int x, String r ) {
        System.out.print( "Sname" );
        System.out.print( '0'+i );
        System.out.print( " : " );
        System.out.print( "My Name is " );
        System.out.print( r );
        System.out.println( Integer.toString(x) );
    }
    private static void xr1( int x ) {
        System.out.print( "value of x : " );
        System.out.println( Integer.toString(x) );
    }

    private static void repeatPrint4() {
        StringBuilder buf = new StringBuilder( 400 );

        for ( int x = 10; x < 2500; x = x + 1 ) {
            pr2( buf, 1, x, "AAAA" );
            pr2( buf, 2, x, "BBBB" );
            pr2( buf, 3, x, "CCCC" );
            pr2( buf, 4, x, "DDDD" );
            pr2( buf, 5, x, "EEEE" );
            xr2( buf, x );

            System.out.print( buf.toString() );

            buf.setLength( 0 );
        }
    }

    private static void pr2( StringBuilder buf, int i, int x, String r ) {
        buf.append( "Sname" );
        buf.append( '0' + i );
        buf.append( " : " );
        buf.append( "My Name is " );
        buf.append( r );
        buf.append( Integer.toString( x ) );
        buf.append( "\n" );
    }
    private static void xr2( StringBuilder buf, int x ) {
        buf.append( "value of x : " );
        buf.append( Integer.toString( x ) );
        buf.append( "\n" );
    }

}

I like your repeatPrint4 but you should add an example with the buffer printed after the loop (and no setLength). — NoDataFound, Aug 30 '14 at 12:04
@NoDataFound the example is there for you to change around, go for it. the purpose of 3 and 4 given above was to highlight the cost of calling system.out.print; it dwarfs everything else. As for moving setLength out, becareful, that will completely change the memory behaviour of the original thing that you were profiling. It will run slower, and could just plain run out of memory :) — Chris K, Aug 30 '14 at 13:56

Manu · Answer 4 · 2014-08-30T10:34:32.903

0

The main reason is that performance is a random variable, so, if you have reliable data to elaborate on, you may first want to produce a reasonable number of data points, so that you can perform a statistical analysis.

edited Aug 30 '14 at 10:34

answered Aug 30 '14 at 10:27

Manu

4,019
8
50
94

I have tested it inside Eclipse, I checked different number of records and seen variation. My question is when I written methods 1 after another performance changed drastically compared with individual testing. – user3924979 Aug 30 '14 at 10:33
Ok, but you are not running any warmup stage, to avoid caching-caused differences. Also, you are not reporting enough data to draw any conclusion on performance. You may want to set up an appropriate benchmark and then report the quantitative results. Without this, any conclusion would be not supported by empirical evidence. – Manu Aug 30 '14 at 10:41

String initialization and performance

4 Answers4