JMX: CPU + Blocked + Wait time = Wall time?

Question

Я пытаюсь использовать JMX для определения того, как долго длился вызов метода, и сколько это было времени процессора, сколько было заблокировано нить и сколько ожидало. В идеале я бы ожидал, что время процессора + время блокировки + время ожидания = время на стене, но я заметил, что это не тот случай - и это не просто слегка неточный таймер. Например:

Wall time: 5657.305 ms 
CPU time: 4060.000 ms (71.77%) 
User time: 3840.000 ms (67.88%) 
Block time: 0.000 ms (0.00%) 
Wait time: 0.000 ms (0.00%) 

Итак, вопрос ... мое предположение, что сумма этих времен (не время пользователя, который включен во времени CPU) должен дать стене время не так? Я что-то упускаю?

Некоторых подробности:

• Стен Время: разница System.currentTimeMillis() на входе методы и выходе время

• ЦП: разность ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime() на входе методы и выходе

• Блок и время ожидания: аналогично процессору, с ManagementFactory.getThreadMXBean().getThreadInfo(Thread.currentThread().getId()).getBlockedTime() и getWaitedTime()

• Да, я знаю, что эти методы возвращают время в разных единицах (ns/ms), я принимаю это во внимание.

• Приложение очень гиперпоточное (4000+ потоков), но я сохраняю всю информацию в потоке, поэтому не должно быть быть любой помехой между вызовами из разных потоков.

Answer 1

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

Однако JVM и ОС должны назначать процессорное время потокам и процессам. В случае необходимости они могут приостановить поток или процесс и возобновить его в любое время. Таким образом, поток может находиться в состоянии, когда он не блокируется и не ждет, а просто не выполняется. Это добавит время стены, но не заблокирует/не будет ждать.

Значение времени процессора поступает из операционной системы. Я проверил OpenJDK 7 для Linux-систем, поэтому на других платформах он может быть другим. Либо fast_thread_cpu_time(), либо slow_thread_cpu_time() вызывается для вычисления времени процессора для потоков. Обе функции расположены в hotspot/src/os/linux/vm/os_linux.cpp источника OpenJDK 7.

С OpenJDK uses pthreads on Linux каждый поток Java реализован как легкий поток ОС. Быстрый метод, поддерживаемый в современных ядрах, вызывает pthread_getcpuclockid для извлечения clock_id для определенного потока, а затем вызывает clock_gettime для получения времени процессора для потока. Медленный метод будет искать значения времени процессора от /proc/self/task/<tid>/stat. Оба метода говорят вам, сколько времени потрачено на использование процессора в пользовательском и системном/ядерном пространстве.

Ссылки:

• OpenJDK 7 source
• pthread_getcpuclockid(3) man page
• clock_gettime(3) man page
• proc(5) man page

Answer 2

Другим способом вы могли бы улучшить точность ваших измерений:

• Выполняйте расчеты в наносекундах, поэтому прошедшее время (с использованием System.nanoTime() и процессорного времени происходит изначально в нано. Время блокировки и ожидания должно быть преобразовано, так как оно находится в миллисекундах.
• Внедрение приближения того, сколько времени требуется, чтобы просто захватить истекшее, CPU, заблокированное и время ожидания. (Назовите это OVERHEAD.) Вы можете сделать это в статическом блоке где-нибудь. Сначала выполните цикл прогрева JVM, имея в виду, что JIT запускается после 15000 вызовов метода [по умолчанию? зависит от вашего JVM ....], поэтому цикл прогрева, по крайней мере, такого размера был бы хорошим.
• Запустите цикл после прогрева, возьмите итоговое истекшее, деленное на количество циклов, и вы получите значение OVERHEAD.
• Вычитайте OVERHEAD из вашего рассчитанного метода, прошедшего время, чтобы получить лучшее представление о времени выполнения кода метода или ...
• Добавить OVERHEAD к вашему добавлению CPU, заблокированному и ожидаемому, чтобы приблизиться к фактическому время стены.
• Опционально пересчитывайте время OVERHEAD.

Это не идеально, и это, безусловно, не требовательно, но это может дать вам несколько лучшие цифры.

Вот некоторый тестовый код, который я запускал, чтобы вычислить среднее значение OVERHEAD (Java 7, Windows 7, 64 бит). Я пытался удостовериться, что никаких методов не было эллипса, но ваш пробег может отличаться.

public class Overhead { 
    static final ThreadMXBean tmx = ManagementFactory.getThreadMXBean(); 
    public static void main(String[] args) { 

     tmx.setThreadContentionMonitoringEnabled(true); 
     tmx.setThreadCpuTimeEnabled(true); 
     int loops = 15000; 
     long sum = -1; 
     long start = System.nanoTime(); 
     for(int i = 0; i < loops; i++) { 
      sum = measure(); 
     } 
     long elapsed = System.nanoTime()-start; 
     log("Warmup completed in [" + elapsed + "] ns. "); 
     log("Sum:" + sum); 

     start = System.nanoTime(); 
     loops = loops * 2; 
     for(int i = 0; i < loops; i++) { 
      sum = measure(); 
     } 
     elapsed = System.nanoTime()-start; 

     long avg = (elapsed/loops); 

     log("Test completed in [" + elapsed + "] ns. OVERHEAD: [" + avg + "] ns."); 
     log("Sum:" + sum); 
    } 

    protected static long measure() { 
     long s1 = System.nanoTime(); 
     long bt = tmx.getCurrentThreadCpuTime(); 
     ThreadInfo ti = tmx.getThreadInfo(Thread.currentThread().getId()); 
     long blocked = ti.getBlockedTime(); 
     long waited = ti.getWaitedTime(); 
     long s2 = System.nanoTime(); 
     return ((s2 - s1) + blocked + waited + bt); 
    } 


    public static void log(Object msg) { 
     System.out.println(msg); 
    } 
} 

Мой выход следующим образом:

Overhead test 
Warmup completed in [43176164] ns. 
Sum:109201929 
Test completed in [38482368] ns. OVERHEAD: [1282] ns. 
Sum:156002228 

Answer 3

С точки зрения исполнения кода, поток может быть запущен, заблокирован на мониторе, или в ожидании гипергликемии. Однако работающий поток должен конкурировать с другими работающими потоками, которые должны быть назначены процессору для запуска - пока он не назначен процессору, он эффективно работает на холостом ходу, не принимая время процессора, но принимая время на стене. Если у вас есть 1000 нитей и несколько ядер процессора, холостой ход может быть значительным. Если это так, вы можете увидеть высокий пользовательский cpu И высокий контекстный переключатель с помощью 'vmstat'.