Initial device instruction seconds after others, despite using NTP offset
Background:
I have two physical devices, a Galaxy S3 (phone) and an Asus 700T (tablet), which I want to execute with the same set of instructions at the same time. So I am using the Android Framework SNTP Client Code to instantiate an SNTP client that receives atomic time, calculates an offset based on the system time, and adds a positive / negative offset to the command execution timestamp so that it will execute in one and the same time (within a few milliseconds) for all devices. I am making a camera flashlight set on / off in one second starting at all values, for example 12: 47: 00.000, because it is noticeable and relatively easy to check if my process is working properly.
Question:
One device tends to start after another (very important 3-5 seconds using a stopwatch).
Case example: S3 ~ .640 seconds for atomic time, 700T ~ 1.100 seconds for atomic time; 700T noticeably starts ~ 3.7 seconds after S3.
Methods used to solve the problem:
There is an Android app, ClockSync , that sets the device to atomic time and claims to be accurate to within 20ms. I compared the calculated offsets with my right before starting my application, and the difference between its offset and mine breaks does not exceed ~ 20ms (for example, Clocksync offset could be 0.620, mine will be no further than 0.640 on S3 or 700T).
I generate timestamps right after flash torch mode is turned off / on and everything is checked, the only difference between devices is that it is possible to get a little ahead of the other, because print times and one device can be about half a second slower than that another.
* Please note that most of the NTP offsets are filtered out due to the fact that their number reduces readability.
The S3 noticeably started first, and the 700T started about 2.130 seconds after the physical stopwatch was at hand.
700T:
Offset according to Clocksync app before starting 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 starting 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, each device requires no more than 30ms to turn the flash on / off, so when not desired, within 30ms after when needed, it doesn't really matter and can't account for the huge difference between triggering on devices.
Code:
In the beginning, I declare a bunch of globals outside of 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 the global variable NTPoffset
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();
}
}
Ways to enable / disable Flash:
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;
}
}
Time stamp 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;
}
}
source to share
You said that you are using the camera flash as a test to test if your approach works, but I think your choice of test case is what bothers you. If this is indeed your ultimate goal for the camera flash to fire at the same time, try choosing something else to test it out. You could make them play sound, but there might be some unpredictable latency in the audio subsystem. A better test would be that you have more explicit control, like blinking something on the screen using the UI, or better yet, blinking something on the screen via GLSurfaceView where you have very fine-grained control over the frame rate and know exactly what latency is.
What I think is happening here is that you have two completely different devices from two different vendors. I don't know for sure, but I'm guessing Samsung has a Samsung camera implementation and it will probably be optimized for low startup lag, so you can pull your phone out of your pocket and take a picture very quickly, Asus makes various compromises (it's a tablet, photography is less important). The devices also certainly use different camera hardware and have different drivers. Therefore, even if you call the camera subsystem almost simultaneously on both devices, they actually respond to this call in different ways. You might have to start another process, send its intent, get a live preview, go out and make a cup of coffee, something like that. As an alternative,if you run the test with two of the same device running the same OS, you will probably get better results.
As a more general comment, I don't know what your overall goals are, but don't expect to be able to achieve simultaneity with too much tolerance - many things work against you. Android is not meant to be a real-time operating system, and even in places where latency is as important as live sound, it has had a chance to guess. The OS might not give you the scheduling latency you want with your process, and Java on Android can be a little unpredictable if you're not very careful about memory allocation and such (garbage collection at the wrong time and everything went out of the window). your process might collide if something else happens. Even your NTP sync in the beginning can be a little fraught, especially if you're syncing over a mobile network connection and not WiFi (although, he said, I don't knowhow well the protocol handles it). Getting things in half a second should be feasible, maybe I think getting things down to less than 10ms would probably be extremely tough, with somewhere in between it would be ... somewhere in the middle.
UPDATE 1
You are using a class android.os.Handler
to run your time. I haven't taken the time to tease your logs and see how close to the one you bump into when both devices wake up and try to signal the outside world, but Handler may not be doing very well with that. If the problem is that the devices don't even think they are very close to each other, measured by their internal clock + NTP timestamp, then you can try something different, for example android.app.AlarmManager
. I don't know if it will be better or worse, but it will be different.
source to share