Timing method duration: always showing zero seconds?

Question

I am trying to time how long a method takes within my application, the issue is that the timing is always showing 0 seconds. What is wrong with my code below?

long currentTimeInMilis = System.currentTimeMillis() % 1000;

    public ClassName() {

        public void timeMethod() {

                long startOfmethod= currentTimeInMilis;

                methodToTime();

                long endOfMethod= currentTimeInMilis;

                long totalTime = endOfMethod= - startOfmethod;

                LOGGER.info("[Method Took: {}", DurationFormatUtils.formatDuration(totalTime, "H:mm:ss", true) + "]\n");                                            
             }
    }

The issue is that I'm getting this output every time, eventhough I know it is taking more than zero seconds :

Method took: 0:0:0:

Set `long endOfMethod=System.currentTimeMillis()` instead of `long endOfMethod= currentTimeInMilis` — A Joshi, Aug 25 '16 at 09:48
Abha Joshi spotted it right. 1-1 will always be right. but the snippet you wrote above, will never take 2 minutes. showing code that 'looks like' the code you're talking about, or that is just 'part' of the code you are talking about, might give trouble in getting the correct view for those trying to find an answer — Stultuske, Aug 25 '16 at 09:50
@Stultuske: *"but the snippet you wrote above, will never take 2 minutes"* We don't know that. The OP hasn't shown the contents of `methodToTime`. (Completely agree with your general point, of course.) — T.J. Crowder, Aug 25 '16 at 09:53
@T.J.Crowder true. but for me, methodOfTime(); if no implementation is given, equals public void methodOfTime(){} that's why I added 'code that is just part of the code'. — Stultuske, Aug 25 '16 at 09:54
What do you get, when you just print *totalTime* and not use *DurationFormatUtils*? I would expect it to be a negative value since you assign the negated *startOfMethod* first to *endOfMethod* and then to *totalTime*. I would also assume that if you would correct that and extend the *DurationFormatUtils* to show years, it might have about **( - 1970)**. — Alexander, Aug 25 '16 at 10:07

score 4 · Accepted Answer · edited May 23 '17 at 11:51

You're using the same currentTimeInMilis variable before and after. It's not like something magically changed it in the meantime (well, unless methodToTime does, since you've made it a field rather than a local variable). You have to actually call System.currentTimeMillis() again after the method is complete in order to have a value you can compare with the value from before the method was called.

E.g., get rid of the currentTimeInMilis field entirely, and see *** below:

public ClassName() {

    public void timeMethod() {

        long startOfmethod = System.currentTimeMillis(); // ***

        methodToTime();

        long endOfMethod = System.currentTimeMillis();   // ***

        long totalTime = endOfMethod = -startOfmethod;

        LOGGER.info("[Method Took: {}", DurationFormatUtils.formatDuration(totalTime, "H:mm:ss", true) + "]\n");
    }
}

Note that I've removed the % 1000 as well; it doesn't make sense to only remember the milliseconds part of the value.

However, note that this is only valid for a very, very rough indication (you've said the method takes two minutes). For proper benchmarking, see How do I write a correct micro-benchmark in Java?

Thanks, this has solved it and I will accept, how less accurate is this than a correct microBenchmark? — java123999, Aug 25 '16 at 09:57
@java123999: See the question and its answers. The above will tell you, with reasonable precision and accuracy, how long **that one call** to `methodToTime` took. But that doesn't mean another call to it will take that long, or that it takes that long on average, or under load, or... The JVM does a lot of on-the-fly optimization; a method that takes a full second to run when run just once may well take a tenth of a second to run if it's being executed in a tight loop, because the JVM (well, Sun/Oracle's JVM) can identify "hotspots" and aggressively optimize them. — T.J. Crowder, Aug 25 '16 at 10:00

Timing method duration: always showing zero seconds?

1 Answers1