Device starting instruction seconds after other despite NTP offset usage

Question

Background:

I have two physical devices, a Galaxy S3 (phone) and an Asus 700T (tablet) that I want to execute the same set of instructions at the exact same time. As such, I'm using Android's Platform Frameworks Base SNTP client code to instantiate a SNTP client which gets the atomic time, calculates an offset based off the system time, and adds the positive/negative offset to the instruction execution timestamp so that it runs at the exact same time (within a few milliseconds) across all devices. I'm doing a set of camera flashlight on/off in one second intervals starting on whole values eg 12:47:00.000 pm because it's noticeable and relatively simple to see if my process is correct.

Issue:

One device tends to start way behind the other (a very noticeable 3-5 seconds using a stopwatch).

Case Example: S3 ~.640 seconds behind atomic time, 700T ~1.100 seconds behind atomic time; 700T visibly starts ~3.7 seconds after S3.

Methods Employed to Solve the Issue:

There is an Android app, ClockSync which sets a device to atomic time and claims to have accuracy within 20ms. I have compared my calculated offsets with its right before running my app and the difference its offset and mine strays no further than ~20ms apart (i.e. Clocksync's offset might be .620, mine would be no further than .640 on either the S3 or 700T).

I generate timestamps right after the flash torch mode gets turned off/on, and things check out, the only difference between devices is that one might be a little ahead of the other because it's printing system time and one device might be about half a second slower than the other.

*Note the bulk of the NTP Offsets have been filtered out due the sheer number of them reducing readability

S3 visibly started first and the 700T started about 2.130 seconds after according to a physical stopwatch I had on hand.

700T:

Offset according to Clocksync app before running my app: 1264

D/NTP Offset﹕ 1254
D/NTP Offset﹕ 1242
D/NTP Offset﹕ 1203
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:1.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:2.203
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:02.217
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:2.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:3.245
D/dalvikvm﹕ GC_CONCURRENT freed 399K, 13% free 3930K/4496K, paused 14ms+1ms, total 46ms
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:03.253
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:3.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:4.231
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:04.236
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:4.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:5.248
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:05.254
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:5.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:6.237
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:06.242
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:6.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:7.243
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:07.255
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:7.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:8.240
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:08.246
D/dalvikvm﹕ GC_FOR_ALLOC freed 366K, 15% free 3910K/4552K, paused 28ms, total 28ms
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:8.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:9.221
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:09.227
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:9.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:10.245
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:10.251

S3:

Offset according to Clocksync app before running my app: 1141

D/NTP Offset﹕ 1136
D/NTP Offset﹕ 1136
D/NTP Offset﹕ 1137
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:1.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:2.137
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:02.156
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:2.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:3.135
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:03.145
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:3.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:4.134
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:04.143
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:4.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:5.135
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:05.144
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:5.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:6.133
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:06.141
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:6.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:7.135
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:07.145
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:7.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:8.133
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:08.142
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:8.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:9.136
D/Flash﹕ Flash torch mode off call hit at 2014-08-15 15:17:09.146
D/instrCal before NTPOffset﹕ 2014-8-15 15:17:9.0
D/instrCal after NTPOffset﹕ 2014-8-15 15:17:10.136
D/Flash﹕ Flash torch mode on call hit at 2014-08-15 15:17:10.146

Based on the stamps it takes no more than 30 ms for each device to turn flash on/off, so while it's not desirable in that it's 30ms after when desired, it's not that big of a difference and can't account for the immense difference between starting on the devices.

Code:

At the beginning I declare a bunch of global variables outside the activity lifecycle methods such as:

PowerManager.WakeLock wakeLock;
private Camera camera;
private boolean isFlashOn;
private boolean hasFlash;
private SQLiteDbAdapter dbHelper;
private SimpleCursorAdapter dataAdapter;
private Handler instrHandler = new Handler();
private int arrayCounter = 0;
private long NTPOffset;
private Calendar NTPcal = Calendar.getInstance();

onStart method

   @Override
    protected void onStart() {
        super.onStart();
        // Needed to ensure CPU keeps running even though user might not touch screen
        PowerManager pm = (PowerManager) getSystemService(Context.POWER_SERVICE);
        wakeLock = pm.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK,
                "Show wakelook");
        wakeLock.acquire();

        new GetNTPServerTimeTask().execute();


        // On starting the app get the camera params
        getCamera();

        // Get ready to pull instructions from SQLite DB
        dbHelper = new SQLiteDbAdapter(this);
        dbHelper.open();

        // Fetch instructions to be used
        final List<DynamoDBManager.EventInstruction> instructionSet = setListFromInstructionQuery();

        final Runnable runnableInstructions = new Runnable() {
            @Override
            public void run() {
                Log.d("top of runnableInstructions timestamp for instruction #" + arrayCounter, getCurrentTimeStamp());
                String instrType = instructionSet.get(arrayCounter).getInstructionType();
                String instrDetail = instructionSet.get(arrayCounter).getInstructionDetail();

                if (instrType.equals("flash")) {
                    if (instrDetail.equals("on")) {
                        turnOnFlash();
                    } else if (instrDetail.equals("off")) {
                        turnOffFlash();
                    }
                }

                // Get the next instruction time
                arrayCounter++;

                // Loop until we're out of instructions
                if (arrayCounter < instructionSet.size()) {
                    String startTime = instructionSet.get(arrayCounter).getInstructionStartTime();
                    Calendar instrCal = convertISO8601StringToCal(startTime);
                    printYMDHMSM("instrCal before NTPOffset", instrCal);
                    instrCal.add(Calendar.MILLISECOND, (int) NTPOffset);
                    printYMDHMSM("instrCal after NTPOffset", instrCal);

                    long diff = instrCal.getTimeInMillis() - System.currentTimeMillis();
                    String sDiff = String.valueOf(diff);
                    Log.d("Timestamp at difference calculation", getCurrentTimeStamp());
                    Log.d("Difference", "Difference " + sDiff);
                    instrHandler.postDelayed(this, diff);
                }
            }
        };

        Runnable runnableInstructionsDelay = new Runnable() {
            @Override
            public void run() {
                Log.d("Timestamp at get first instruction time", getCurrentTimeStamp());
                String startTime = instructionSet.get(arrayCounter).getInstructionStartTime();
                Calendar instrCal = convertISO8601StringToCal(startTime);
                printYMDHMSM("First instr instrCal before NTPOffset", instrCal);
                instrCal.add(Calendar.MILLISECOND, (int) NTPOffset);
                printYMDHMSM("First instr instrCal after NTPOffset", instrCal);

                long diff = instrCal.getTimeInMillis() - System.currentTimeMillis();
                instrHandler.postDelayed(runnableInstructions, diff);
            }
        };

        // Get the first instruction time
        if (arrayCounter < instructionSet.size() && arrayCounter == 0) {
            // Since activity gets auto-switched to 30 seconds before first instruction timestamp we want to 
            // use only the most recent NTP offset right before launching the instruction set
            instrHandler.postDelayed(runnableInstructionsDelay, 25000);
        }
    }

NTP offset Async Task that loops and sets a global NTPoffset variable

public class GetNTPServerTimeTask extends
            AsyncTask<Void, Void, Void> {

        long NTPnow = 0;

        @Override
        protected Void doInBackground(Void... voids
        ) {

            SntpClient client = new SntpClient();
            if (client.requestTime("0.north-america.pool.ntp.org", 10000)) {
                NTPnow = client.getNtpTime() + SystemClock.elapsedRealtime() - client.getNtpTimeReference();
                NTPcal.setTime(new Date(NTPnow));
                // If NTPCal is ahead, we want the value to be positive so we can add value to system clock to match
                NTPOffset = NTPcal.getTimeInMillis() - System.currentTimeMillis();

                // Time debugging
                Log.d("NTP Now", String.valueOf(NTPnow));
                Log.d("NTP SystemTime", String.valueOf(System.currentTimeMillis()));
                Log.d("NTP Offset", String.valueOf(NTPOffset));
                printYMDHMSM("Calendar Instance", Calendar.getInstance());
                printYMDHMSM("NTPCal Value", NTPcal);
            }
            return null;
        }
    @Override
    protected void onPostExecute(Void aVoid) {
        super.onPostExecute(aVoid);
        new GetNTPServerTimeTask().execute();
    }
}

Flash on/off methods:

private void turnOnFlash() {
    if (!isFlashOn) {
        if (camera == null || params == null) {
            return;
        }

        params = camera.getParameters();
        params.setFlashMode(Camera.Parameters.FLASH_MODE_TORCH);
        Log.d("Flash", "Flash torch mode on call hit at " + getCurrentTimeStamp());
        camera.setParameters(params);
        camera.startPreview();
        isFlashOn = true;
    }

}

private void turnOffFlash() {
    if (isFlashOn) {
        if (camera == null || params == null) {
            return;
        }

        params = camera.getParameters();
        params.setFlashMode(Camera.Parameters.FLASH_MODE_OFF);
        Log.d("Flash", "Flash torch mode off call hit at " + getCurrentTimeStamp());
        camera.setParameters(params);
        camera.stopPreview();
        isFlashOn = false;
    }
}

Timestamp method I wrote:

public static String getCurrentTimeStamp() {
    try {

        SimpleDateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
        String currentTimeStamp = dateFormat.format(new Date()); // Find todays date

        return currentTimeStamp;
    } catch (Exception e) {
        e.printStackTrace();

        return null;
    }
}

Answer 1

You said that you were using the camera flash just as a test to see if your approach is working, but I think your choice of a test case is what's getting you into trouble. Unless it really is your end goal to have the camera flashes fire at the same time, try choosing something different to test it. You could have them play a sound, but there may be some unpredictable latency in the audio subsystem -- a better test would be something where you have more explicit control, like flashing something on the screen via the UI framework, or better yet, flashing something on the screen via GLSurfaceView, where you have very fine-grained control over the frame rate and know exactly what the latency should be.

I think what's happening here is that you have two completely different devices from two different vendors. I don't know for certain, but I'm guessing the Samsung has a Samsung-supplied camera implementation, and it's likely to be optimized for low startup latency, so you can pull the phone out of your pocket and take a picture very quickly. The Asus makes different tradeoffs (it's a tablet, photography is less important). The devices also certainly use different camera hardware and have different drivers. So even though you're making the call to the camera subsystem nearly simultaneously on both devices, they actually respond to that call differently. It may have to fire up another process, send it an intent, get the live camera preview going, go out and make a cup of coffee, that sort of thing. Alternately, if you would run the test with two of the same device running the same OS, you would probably get better results.

As a more general comment, I don't know what your overall goals are, but don't get your hopes up for being able to achieve simultaneity within too tight a tolerance -- a lot of things are working against you. Android isn't designed as a real-time OS, and even in places where latency is important like live audio, it's got some catching up to do. The OS may not give you the scheduling latency you want with your process, and Java on Android can be a little unpredictable unless you're very careful about memory allocation and such (a garbage collection at the wrong time and everything is out the window). Your process can get bumped around at any time if something else occurs. Even your NTP synchronization at the beginning can be a little fraught, especially if you're synchronizing over a mobile network connection and not WiFi (though having said that, I don't know how good the protocol is at dealing with that). Getting things to within a half-second should be feasible, maybe, I think, getting things to less than 10ms is likely to be extremely tough, and somewhere in between will be...somewhere in between.

UPDATE 1

You're using the android.os.Handler class to do your timing. I haven't taken the time to tease out your logs and see how close to simultaneous you're getting with when both devices are woken up and attempt to signal to the outside world, but Handler may not do a very good job at it. If part of the problem is that the devices don't even think they're getting very close to each other, measured by their internal clock + NTP timestamp, then you could try something different, like android.app.AlarmManager. Don't know if that will be better or worse, but it will be different.