System.nanoTime() gives wrong times in Android

Question

I am developing a game where some events happen after some predetermined amounts of time. For that I need to calculate how much time has elapsed from the starting of the game. I do that by launching a thread in the main loop and computing the time elapsed with System.nanoTime().

I have tested the code on my smartphone and it works pretty well as long as I do not press the sleep button putting the phone in sleep (which triggers the onpause() method of the activity). But sometimes when I press the sleep button some very strange things: it seems that System.nanoTime() gives times greater than they actually are (never smaller by the way).

I have tried using System.currentTimeMillis() in place of System.nanoTime() but things are even worse (I know that there was some issues with System.nanoTime() on Windows systems with multi-core devices; by the way my smartphone is also multi-core).

Here is the code:

import android.app.Activity;
import android.os.Bundle;
import android.util.Log;
import android.widget.TextView;

public class MainActivity extends Activity implements Runnable {

   private Thread gameThread = null;
   private volatile boolean running = false;

   private long startTime;
   private long totalTime;

   private boolean[] afterNSeconds = new boolean[11];
   private static long oneBillion = 1000000000;

   @Override
   public void onCreate(Bundle savedInstanceState) {
      super.onCreate(savedInstanceState);

      TextView tv = new TextView(getApplicationContext());
      tv.setText("Start");
      setContentView(tv);
   }

   @Override
   public void onResume() {
      super.onResume();
      running = true;
      gameThread = new Thread(this);
      gameThread.start();
   }

   @Override
   public void onPause() {
      super.onPause();

      totalTime = System.nanoTime() - startTime;

      running = false;
      while (true) {
         try {
            gameThread.join();
            return;
         } catch (InterruptedException e) {
            e.printStackTrace();
         }
      }
   }

   @Override
   public void run() {
      startTime = System.nanoTime();

      while (running) {

         long elapsedTime = totalTime + System.nanoTime()
               - startTime;

         for (int j = 1; j <= 10; j++) {

            if (elapsedTime >= j * oneBillion
                  && !afterNSeconds[j]) {
               Log.d("MainActivity", j + ": elapsedTime = "
                     + elapsedTime );
               afterNSeconds[j] = true;
            }
         }
      }
   }
}

Here is a normal output when I do not press the sleep button:

01-07 23:56:40.722: D/MainActivity(26579):  1: elapsedTime =  1021247230 
01-07 23:56:41.708: D/MainActivity(26579):  2: elapsedTime =  2007078538 
01-07 23:56:42.701: D/MainActivity(26579):  3: elapsedTime =  3000023615 
01-07 23:56:43.701: D/MainActivity(26579):  4: elapsedTime =  4000000538 
01-07 23:56:44.701: D/MainActivity(26579):  5: elapsedTime =  5000000846 
01-07 23:56:45.701: D/MainActivity(26579):  6: elapsedTime =  6000001230 
01-07 23:56:46.701: D/MainActivity(26579):  7: elapsedTime =  7000001384 
01-07 23:56:47.701: D/MainActivity(26579):  8: elapsedTime =  8000001923 
01-07 23:56:48.701: D/MainActivity(26579):  9: elapsedTime =  9000000769 
01-07 23:56:49.701: D/MainActivity(26579): 10: elapsedTime = 10000002000

And here is an anomalous output when I pressed the sleep button after 3 seconds and repressed again after some seconds. (The anomalous behavior is from 4 to 6) As you can see, after less than 4 seconds have passed System.nanoTime() reports 6 seconds instead.

01-08 00:02:48.645: D/MainActivity(26579):  1: elapsedTime =  1001408231 
01-08 00:02:49.644: D/MainActivity(26579):  2: elapsedTime =  2000000615
01-08 00:02:50.644: D/MainActivity(27265):  3: elapsedTime =  3000000539 

01-08 00:02:50.802: D/MainActivity(27265):  4: elapsedTime =  6000000462
01-08 00:02:50.802: D/MainActivity(27265):  5: elapsedTime =  6000000462
01-08 00:02:50.802: D/MainActivity(27265):  6: elapsedTime =  6000000462

01-08 00:03:21.358: D/MainActivity(27265):  7: elapsedTime =  7000000770
01-08 00:03:22.358: D/MainActivity(27265):  8: elapsedTime =  8000000539
01-08 00:03:23.358: D/MainActivity(27265):  9: elapsedTime =  9000000154
01-08 00:03:23.730: D/MainActivity(27265): 10: elapsedTime = 10000003847

How can I modify my code to avoid this behavior?

It seems that you're busy looping in your background thread, doing so you will kill your battery after an hour or so... — pskink, Jan 08 '15 at 14:17

Richard Tingle · Answer 1 · 2015-01-08T14:08:46.353

2

SystemClock is the appropriate clock to use on android

Specifically SystemClock.elapsedRealtime() gives the time since the system was booted which (unlike System.currentTimeMillis()) isn't affected by hour changes/user action and (unlike uptimeMillis()) includes time in deep sleep

edited Jan 08 '15 at 14:08

answered Jan 08 '15 at 14:01

Richard Tingle

16,906
5
52
77

Thank you for your answer. SystemClock computes the time elapsed since booting; is there a way to compute the time from an arbitrary event? – CHebdo Jan 08 '15 at 14:11
@CHebdo Well System.currentTimeMillis() will give you the milliseconds since 1/1/1970 **but** can jump when the user manually changes their system clock. Must you get the time since an event which occurred before a system restart/shutdown? – Richard Tingle Jan 08 '15 at 14:24
I have tried System.currentTimeMillis() but it gives even more strange behavior than System.nanoTime(). – CHebdo Jan 08 '15 at 14:49
@CHebdo Strange in what way? – Richard Tingle Jan 08 '15 at 14:58
1

Can't you cache the SystemClock reading at start time and compare it to the current reading? – nasch Jan 08 '15 at 23:18

System.nanoTime() gives wrong times in Android

1 Answers1