Синхронизированный блок занимает больше времени после инструментирования с помощью ASM

Я пытаюсь использовать синхронизированный блок Java с помощью ASM. Проблема в том, что после инструментирования время выполнения синхронизированного блока занимает больше времени. Здесь оно увеличивается с 2 мс до 200 мс на Linux.

Я реализую это, идентифицируя код операции MonitorEnter и MonitorExit.

Я пытаюсь инструментировать на трех уровнях 1. непосредственно перед MonitorEnter 2. после MonitorEnter 3. Перед MonitorExit. 1 и 3 вместе работают нормально, но когда я делаю 2, время выполнения резко увеличивается.

Даже если мы настроим еще один SOP-оператор, предназначенный для однократного выполнения, он даст более высокие значения. Вот пример кода (простое число, 10 циклов):

for(int w=0;w<10;w++){
synchronized(s){
  long t1 = System.currentTimeMillis();
  long num = 2000;
for (long i = 1; i < num; i++) {
        long p = i;
    int j;
    for (j = 2; j < p; j++) {
            long n = p % i;
        }
    }
long t2 = System.currentTimeMillis();
 System.out.println("Time>>>>>>>>>>>> " + (t2-t1) );
}

Здесь код для инструментария (здесь System.currentMilliSeconds() дает время, когда произошло инструментирование, это не показатель времени выполнения, время выполнения указано в предыдущем операторе SOP):

  public void visitInsn(int opcode)
    {
        switch(opcode)
        {
          // Scenario 1
        case 194: 
            visitFieldInsn(Opcodes.GETSTATIC, "java/lang/System", "out", "Ljava/io   /PrintStream;");
            visitLdcInsn("TIME Arrive: "+System.currentTimeMillis());
            visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V");
            break;

        // scenario 3
        case 195: 
            visitFieldInsn(Opcodes.GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
            visitLdcInsn("TIME exit : "+System.currentTimeMillis());
            visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V");
            break;
        }

        super.visitInsn(opcode);

       // scenario 2
       if(opcode==194)
        {
            visitFieldInsn(Opcodes.GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
            visitLdcInsn("TIME enter: "+System.currentTimeMillis());
            visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V");

        }

        }

Я не могу найти причину, почему это происходит и как это исправить.

Заранее спасибо.


person user3032258    schedule 25.11.2013    source источник
comment
Вы не измеряете саму синхронизацию, так как оба currentTimeMillis вызова находятся в синхронизированном блоке. Кстати, что такое s? Что вы знаете о конфликте, происходящем при синхронизации этого объекта?   -  person Holger    schedule 25.11.2013
comment
s — это объект String, для которого выполняется синхронизация. здесь я использую только один поток, а блок синхронизации выполняется 10 раз. Каждый раз (t2-t1) рассчитывается время. Я использую currentTimeMillis внутри блока, потому что это время обслуживания этого блока, одинаковое для всех потоков. Это мой мотив, поэтому он так сильно увеличивается после инструментовки. Пожалуйста, не рассматривайте спорную часть прямо сейчас. По крайней мере, время выполнения должно остаться прежним.   -  person user3032258    schedule 25.11.2013
comment
Вы измеряете способность JVM оптимизировать неиспользуемый/бессмысленный код, и кажется, что добавление оператора печати (эффект которого виден снаружи) в определенном месте нарушает оптимизацию. Кстати, String — необычный объект для синхронизации. Не рекомендуется.   -  person Holger    schedule 25.11.2013
comment
Мое намерение состоит в том, чтобы вызвать функцию, которая принимает метки времени на трех уровнях, а затем путем вычитания я могу рассчитать время прибытия, время ожидания блокировки для определенного потока. Раньше у меня была функция, которая брала временные метки на этих уровнях, но это увеличивало время выполнения. Вот почему я ставлю СОП. Но не могли бы вы сказать мне, как я могу увидеть, какие оптимизации выполняет JVM. Кстати, вызов SOP или функции находится вне цикла for, как это влияет на оптимизацию. Любое решение этого.   -  person user3032258    schedule 25.11.2013
comment
Пожалуйста, ответьте на это: Подробнее. Более того, если я прямо поставлю оператор SOP на вход блока синхронизации в файле .java, а затем запущу его, время выполнения останется прежним. Почему он увеличивается, если я делаю это с помощью инструментов.   -  person user3032258    schedule 25.11.2013
comment
Оптимизатор будет обрабатывать блоки кода, чтобы ваша SOP могла влиять на него или нет. Очень вероятно, что SOP до monitorenter или после monitorexit не имеет никакого значения, поскольку это естественные границы, но вы даже не можете полагаться на это, так как JVM может попытаться оптимизировать и саму синхронизацию. Напомню простую вещь: инструментарий влияет на тайминг. И чем меньше время измерения (а вы охотитесь за очень маленькими интервалами), тем больше становится проблема. Так что не делайте этого; использовать встроенные возможности мониторинга JVM.   -  person Holger    schedule 25.11.2013
comment
Просто попробуйте сделать это: `sychronized(s){ System.out.println(Entered); *все остальное там остается прежним*\ ` Напишите SOP непосредственно в java-файле, а затем напишите с помощью инструментария. Сравните тайминги.   -  person user3032258    schedule 25.11.2013
comment
Почему я должен это делать? Я уже говорил вам, что инструментарий влияет на тайминг. Оптимизатор находится вне вашего контроля. Вам придется принять этот факт. Вы можете найти причину, если будете проводить расследование достаточно долго, но это вам не поможет. Небольшое изменение в следующем выпуске JVM, и вы снова столкнетесь с теми же проблемами.   -  person Holger    schedule 25.11.2013
comment
Ok. Итак, оптимизация происходит во время компиляции или во время выполнения? Любые предложения статьи, если вы могли бы предоставить.   -  person user3032258    schedule 25.11.2013
comment
Во время выполнения. Ключевые слова: «JIT» и «оптимизатор Hotspot».   -  person Holger    schedule 25.11.2013


Ответы (1)


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

Если вы активируете следующий код:

int result = 0;
for(int i = 0; i < 1000; i++) {
  result += i;
}

Это будет транслировано компилятором Java непосредственно в байт-код Java, но во время выполнения JVM легко увидит, что этот код ничего не делает. Выполнение этого кода не повлияет на внешний мир (приложение), так почему же JVM должна его выполнять? Именно это соображение делает для вас оптимизация компилятора.

Однако если вы активируете следующий код:

int result = 0;
for(int i = 0; i < 1000; i++) {
  System.out.println(result);
}

среда выполнения Java больше не может оптимизировать ваш код. Весь цикл всегда должен выполняться, так как метод System.out.println(int) всегда делает что-то настоящее, поэтому ваш код будет работать медленнее.

Теперь давайте посмотрим на ваш пример. В вашем первом примере вы в основном пишете этот код:

synchronized(s) {
   // do nothing useful
}

Весь этот блок кода может быть легко удален во время выполнения Java. Это означает: Синхронизации не будет! Во втором примере вместо этого вы пишете следующее:

synchronized(s) {
   long t1 = System.currentTimeMillis();
   // do nothing useful
   long t2 = System.currentTimeMillis();
   System.out.println("Time>>>>>>>>>>>> " + (t2-t1));
}

Это означает, что эффективный код может выглядеть так:

synchronized(s) {
   long t1 = System.currentTimeMillis();
   long t2 = System.currentTimeMillis();
   System.out.println("Time>>>>>>>>>>>> " + (t2-t1));
}

Здесь важно то, что этот оптимизированный код будет эффективно синхронизирован, что является важной разницей в отношении времени выполнения. По сути, вы измеряете время, необходимое для синхронизации чего-либо (и даже это может быть оптимизировано после пары прогонов, если JVM поймет, что s не заблокировано где-либо еще в вашем коде (модное слово: временная оптимизация с возможностью деоптимизация, если загружаемый код в будущем также будет синхронизироваться на s).

Вы действительно должны прочитать это:

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

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

person Rafael Winterhalter    schedule 26.11.2013