Инструкция по запуску устройства через несколько секунд после другой, несмотря на использование смещения NTP

Предыстория:

У меня есть два физических устройства: Galaxy S3 (телефон) и Asus 700T (планшет), которые я хочу выполнять в одно и то же время с одним и тем же набором инструкций. Таким образом, я использую платформу Android Platform Frameworks Base. Код клиента SNTP для создания экземпляра клиента SNTP, который получает атомарное время, вычисляет смещение на основе системного времени и добавляет положительное/отрицательное смещение к отметке времени выполнения инструкции, чтобы он выполнялся в то же самое время (в пределах несколько миллисекунд) на всех устройствах. Я делаю набор включения/выключения фонарика камеры с интервалом в одну секунду, начиная с целых значений, например, 12:47:00.000, потому что это заметно и относительно просто увидеть, правильный ли мой процесс.

Проблема:

Одно устройство имеет тенденцию запускаться намного позже другого (очень заметные 3-5 секунд при использовании секундомера).

Пример: S3 ~0,640 секунды отстаёт от атомного времени, 700T ~1,100 секунды отстаёт от атомного времени; 700T заметно запускается примерно через 3,7 секунды после S3.

Методы, используемые для решения проблемы:

Существует приложение для Android, ClockSync. который устанавливает устройство на атомное время и утверждает, что имеет точность в пределах 20 мс. Я сравнил свои рассчитанные смещения с его правым перед запуском моего приложения, и разница между его смещением и моим не превышает ~ 20 мс (т.е. смещение Clocksync может быть 0,620, мое будет не более 0,640 на S3 или 700T). ).

Я генерирую временные метки сразу после выключения/включения режима вспышки, и все проверяется, единственная разница между устройствами заключается в том, что одно может немного опережать другое, потому что это системное время печати, а одно устройство может быть примерно на полсекунды медленнее другого.

* Обратите внимание, что большая часть смещений NTP была отфильтрована из-за того, что их огромное количество снижает читабельность.

S3 заметно стартовал первым, а 700T стартовал примерно через 2,130 секунды после него, судя по физическому секундомеру, который у меня был под рукой.

700T:

Смещение в соответствии с приложением Clocksync перед запуском моего приложения: 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:

Смещение в соответствии с приложением Clocksync перед запуском моего приложения: 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

Судя по штампам, каждому устройству требуется не более 30 мс, чтобы включить/выключить вспышку, поэтому, хотя это и нежелательно, поскольку при желании это происходит через 30 мс, это не такая уж большая разница и не может объяснить огромную разницу. между запуском на устройствах.

Код:

В начале я объявляю кучу глобальных переменных вне методов жизненного цикла активности, таких как:

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

   @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 Асинхронная задача, которая зацикливается и устанавливает глобальную переменную 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();
    }
}

Методы включения/выключения вспышки:

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;
    }
}

Метод отметки времени, который я написал:

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;
    }
}

person Kurt Wagner    schedule 15.08.2014    source источник
comment
Если бы вы могли немного уточнить свой вопрос, это помогло бы. Я понимаю, что в реальном времени одно устройство отстает от другого, но не совсем ясно, (а) действительно ли синхронизированы часы устройств и (б) думают ли устройства, что они выполняют код в нужное время. Кроме того, код, который вы включили, не генерирует вывод в вопросе - я не вижу, где генерируются эти журналы включения / выключения режима факела. Я не вижу, что такое класс instrHandler. Наиболее вероятное предположение состоит в том, что instrHandler может не давать никаких гарантий относительно того, когда что-то заработает — только минимальную задержку.   -  person Scott Barta    schedule 15.08.2014
comment
Я добавил рассматриваемый код, в настоящее время я получаю более полный набор журналов для добавления, но это может занять некоторое время, потому что AS, похоже, не поддерживает сеансы LogCat, работающие одновременно. Из логов я так понимаю они синхронизируются. Телефон, скажем, на 0,650 секунды отстает от атомарного, инструкция должна запускаться, скажем, в 1:00:00, журналы вызовов флэш-памяти 1:00:00,680 (смещение + 30 мс, чтобы нажать flash instr). Планшет имеет смещение, скажем, 1,100, выводит системное время у flash примерно 1:00:01.130, значит по логам они должны синхронизироваться, но визуально далеки от этого.   -  person Kurt Wagner    schedule 15.08.2014


Ответы (1)


Вы сказали, что использовали вспышку камеры просто как тест, чтобы увидеть, работает ли ваш подход, но я думаю, что ваш выбор тестового примера - это то, что доставляет вам неприятности. Если на самом деле вашей конечной целью не является одновременное срабатывание вспышек камеры, попробуйте выбрать что-то другое, чтобы проверить это. Вы можете заставить их воспроизводить звук, но в звуковой подсистеме может быть некоторая непредсказуемая задержка — лучшим тестом будет что-то, где у вас есть более явный контроль, например, мигание чего-то на экране через инфраструктуру пользовательского интерфейса или, что еще лучше, мигание что-то на экране через GLSurfaceView, где вы имеете очень тонкий контроль над частотой кадров и точно знаете, какой должна быть задержка.

Я думаю, что здесь происходит то, что у вас есть два совершенно разных устройства от двух разных производителей. Я не знаю наверняка, но я предполагаю, что у Samsung есть реализация камеры, предоставленная Samsung, и она, вероятно, оптимизирована для низкой задержки запуска, поэтому вы можете вытащить телефон из кармана и сделать снимок очень быстро. . Asus идет на разные компромиссы (это планшет, фотография менее важна). Устройства также, безусловно, используют разное аппаратное обеспечение камеры и разные драйверы. Таким образом, хотя вы почти одновременно звоните в подсистему камеры на обоих устройствах, на самом деле они реагируют на этот вызов по-разному. Возможно, ему придется запустить другой процесс, отправить ему намерение, запустить предварительный просмотр камеры в реальном времени, выйти и приготовить чашку кофе и тому подобное. С другой стороны, если вы запустите тест на двух одинаковых устройствах с одной и той же ОС, вы, вероятно, получите лучшие результаты.

В качестве более общего комментария: я не знаю, каковы ваши общие цели, но не надейтесь на то, что вы сможете достичь одновременности в рамках слишком жестких допусков — многое работает против вас. Android не разработан как ОС реального времени, и даже там, где задержка важна, например, в живом звуке, ему нужно наверстать упущенное. ОС может не дать вам желаемой задержки планирования с вашим процессом, а Java на Android может быть немного непредсказуемой, если вы не будете очень осторожны с распределением памяти и т. д. (сборка мусора в неподходящее время и все вне окна) . Ваш процесс может быть нарушен в любое время, если произойдет что-то еще. Даже ваша NTP-синхронизация в начале может быть немного чревата, особенно если вы синхронизируетесь через мобильное сетевое соединение, а не через WiFi (хотя, сказав это, я не знаю, насколько хорошо протокол справляется с этим). Достижение результата за полсекунды должно быть осуществимым, может быть, я думаю, что получить результат менее 10 мс, вероятно, будет чрезвычайно сложно, и где-то посередине будет ... где-то посередине.

ОБНОВЛЕНИЕ 1

Вы используете класс android.os.Handler для измерения времени. Я не тратил время на то, чтобы дразнить ваши журналы и посмотреть, насколько вы близки к одновременному, когда оба устройства просыпаются и пытаются подать сигнал внешнему миру, но обработчик может не очень хорошо с этим справиться. Если часть проблемы заключается в том, что устройства даже не думают, что они очень близки друг к другу, что измеряется их внутренними часами + временной меткой NTP, вы можете попробовать что-то другое, например android.app.AlarmManager. Не знаю, будет лучше или хуже, но будет по-другому.

person Scott Barta    schedule 15.08.2014
comment
Я изменил его на что-то менее аппаратно-зависимое: View root = ((ViewGroup) findViewById(android.R.id.content)).getChildAt(0); root.setBackgroundColor(Color.rgb(255, 0, 0));, но по-прежнему работает с начальной разницей времени около 2+ секунд, поэтому я немного скептически отношусь к банкомату относительно того, насколько возможно сузить до полсекунды. Собираюсь попробовать GLSurfaceView, но, поскольку я новичок в этом, мне может потребоваться некоторое время, чтобы сообщить о своих выводах. - person Kurt Wagner; 16.08.2014
comment
GLSurfaceView не будет иметь большого значения, если вы находитесь в 2+ секундах - это уменьшит задержку на порядок 1 или 10 мс. Я бы посоветовал вам сократить вашу тестовую программу до минимума — например, там есть Sqlite, вырвите его. Сделайте свой журнал очень простым для понимания - вы показываете временные метки и смещения, и читатель SO может не тратить время на то, чтобы действительно разобраться в этом. Также я добавлю больше к своему ответу об instrHandler. - person Scott Barta; 16.08.2014
comment
Улучшив ведение журнала, я бы предложил отображать временную метку устройства на основе часов, а затем также отображать исправленную временную метку, учитывающую смещение NTP — таким образом можно легко сравнивать яблоки с яблоками между устройствами. - person Scott Barta; 16.08.2014
comment
Я обновил вопрос, чтобы включить лучший набор журналов, чтобы проиллюстрировать проблему, теперь работая над реализацией AlarmManager. - person Kurt Wagner; 16.08.2014
comment
Я думаю, что нашел проблему; Мне еще предстоит внедрить решение AlarmManager, но я новичок в отладке и всегда игнорировал сообщение dalvikvm: GC_CONCURRENT, которое появлялось на моем планшете, но не на моем телефоне (что объясняет, почему планшет отстает). Код работает примерно 30 секунд, он ожидает первую инструкцию и продолжает вычислять смещение NTP (также вычисляется во время выполнения инструкции). Чтобы предотвратить сборку мусора, я должен просто поместить все объявления переменных в начало своей деятельности и объявить их все статическими? Я не слишком хорошо знаком с gc opt - person Kurt Wagner; 19.08.2014
comment
Как я выяснил, AlarmManager + Broadcast Receiver не является жизнеспособным решением; код включения/выключения вспышки происходит примерно через секунду после того, как объект календаря передается в AlarmManager, где, как и в моем решении выше, это ‹= 20 мс. На данный момент похоже, что GC_CONCURRENT является виновником, поэтому мне придется провести расследование кучи. - person Kurt Wagner; 22.08.2014