Tại sao System.nanoTime() của tôi bị hỏng?

Question

Bản thân tôi và một nhà phát triển khác trên thời gian của tôi gần đây đã chuyển từ máy tính Core 2 Duo sang Core 2 Quad 9505 mới; cả hai đều chạy Windows XP SP3 32 bit với JDK 1.6.0_18.

Khi làm như vậy, một vài thử nghiệm đơn vị tự động của chúng tôi cho một số mã thời gian/thống kê/số liệu tổng hợp bắt đầu thất bại, do những giá trị vô lý trở lại từ System.nanoTime().

mã kiểm tra cho thấy hành vi này, đáng tin cậy, trên máy tính của tôi là:

import static org.junit.Assert.assertThat; 

import org.hamcrest.Matchers; 
import org.junit.Test; 

public class NanoTest { 

    @Test 
    public void testNanoTime() throws InterruptedException { 
    final long sleepMillis = 5000; 

    long nanosBefore = System.nanoTime(); 
    long millisBefore = System.currentTimeMillis(); 

    Thread.sleep(sleepMillis); 

    long nanosTaken = System.nanoTime() - nanosBefore; 
    long millisTaken = System.currentTimeMillis() - millisBefore; 

    System.out.println("nanosTaken="+nanosTaken); 
    System.out.println("millisTaken="+millisTaken); 

    // Check it slept within 10% of requested time 
    assertThat((double)millisTaken, Matchers.closeTo(sleepMillis, sleepMillis * 0.1)); 
    assertThat((double)nanosTaken, Matchers.closeTo(sleepMillis * 1000000, sleepMillis * 1000000 * 0.1)); 
    } 

} 

sản lượng tiêu biểu:

millisTaken=5001 
nanosTaken=2243785148 

Chạy nó sản lượng 100x kết quả nano giữa 33% và 60% so với thực tế giờ ngủ; thường là khoảng 40%.

Tôi hiểu điểm yếu về độ chính xác của bộ tính giờ trong Windows và đã đọc các chủ đề có liên quan như Is System.nanoTime() consistent across threads?, tuy nhiên, hiểu biết của tôi là System.nanoTime() nhằm mục đích chính xác mục đích chúng tôi đang sử dụng: - đo thời gian trôi qua; chính xác hơn currentTimeMillis().

Có ai biết tại sao nó trả về kết quả điên rồ như vậy không? Đây có phải là một vấn đề kiến ​​trúc phần cứng (điều duy nhất đã thay đổi là CPU/Bo mạch chủ trên máy này)? Một vấn đề với Windows HAL với phần cứng hiện tại của tôi? Một vấn đề JDK? Tôi có nên từ bỏ nanoTime() không? Tôi có nên đăng nhập một lỗi ở đâu đó hoặc bất kỳ đề xuất nào về cách tôi có thể điều tra thêm không?

CẬP NHẬT 19/07 03:15 UTC: Sau khi thử trường hợp thử nghiệm của finnw bên dưới, tôi đã thực hiện một số Googling khác, đi qua các mục như bugid:6440250. Nó cũng nhắc nhở tôi về một số hành vi kỳ lạ khác mà tôi nhận thấy vào cuối ngày thứ Sáu, nơi ping đã trở lại tiêu cực. Vì vậy, tôi đã thêm /usepmtimer vào boot.ini của tôi và bây giờ tất cả các thử nghiệm hoạt động như mong đợi., Và ping của tôi cũng bình thường.

Tôi hơi bối rối vì sao đây vẫn là vấn đề; từ đọc sách của tôi, tôi nghĩ rằng TSC vs PMT vấn đề đã được giải quyết phần lớn trong Windows XP SP3. Có thể vì máy của tôi ban đầu là SP2 và được vá thành SP3 thay vì được cài đặt ban đầu là SP3? Tôi bây giờ cũng tự hỏi liệu tôi có nên cài đặt các bản vá lỗi như một cái ở số MS KB896256 hay không. Có lẽ tôi nên thực hiện điều này với nhóm xây dựng máy tính để bàn của công ty?

Answer 1

Vấn đề đã được giải quyết (với một số nghi ngờ cởi mở về sự phù hợp của nanoTime() trên các hệ thống đa lõi!) Bằng cách thêm /usepmtimer đến hết C của tôi: \ boot.ini chuỗi; buộc Windows phải sử dụng bộ hẹn giờ Quản lý nguồn thay vì TSC. Đó là một câu hỏi mở là tại sao tôi cần phải làm điều này cho tôi là trên XP SP3, như tôi hiểu rằng đây là mặc định, tuy nhiên có lẽ đó là do cách thức mà máy của tôi đã được vá đến SP3.

Answer 2

Bạn có thể muốn đọc câu trả lời cho câu hỏi tràn ngăn xếp khác này: Is System.nanoTime() completely useless?.

Tóm lại, có vẻ như nanoTime phụ thuộc vào bộ hẹn giờ của hệ điều hành có thể bị ảnh hưởng bởi sự hiện diện của nhiều CPU lõi. Như vậy, nanoTime có thể không hữu ích đối với các kết hợp nhất định của hệ điều hành và CPU, và cần lưu ý khi sử dụng nó trong mã Java di động mà bạn dự định chạy trên nhiều nền tảng đích. Dường như có rất nhiều phàn nàn trên trang web về chủ đề này, nhưng không có nhiều sự đồng thuận về một sự thay thế có ý nghĩa.

Answer 3

Trên hệ thống của tôi (Windows 7 64-Bit, Core i7 980X):

nanosTaken=4999902563 
millisTaken=5001 

System.nanoTime() sử dụng các cuộc gọi hệ điều hành cụ thể, vì vậy tôi hy vọng rằng bạn đang nhìn thấy một lỗi trong Windows của bạn/bộ xử lý kết hợp.

Answer 4

Rất khó để biết đây là lỗi hay chỉ là sự thay đổi thời gian bình thường giữa các lõi.

Thử nghiệm bạn có thể thử là sử dụng cuộc gọi gốc để buộc luồng chạy trên một lõi cụ thể.

Ngoài ra, để loại trừ ảnh hưởng quản lý điện năng, hãy thử quay trong một vòng lặp như một thay thế cho sleep():

import com.sun.jna.Native; 
import com.sun.jna.NativeLong; 
import com.sun.jna.platform.win32.Kernel32; 
import com.sun.jna.platform.win32.W32API; 

public class AffinityTest { 

    private static void testNanoTime(boolean sameCore, boolean spin) 
    throws InterruptedException { 
     W32API.HANDLE hThread = kernel.GetCurrentThread(); 
     final long sleepMillis = 5000; 

     kernel.SetThreadAffinityMask(hThread, new NativeLong(1L)); 
     Thread.yield(); 
     long nanosBefore = System.nanoTime(); 
     long millisBefore = System.currentTimeMillis(); 

     kernel.SetThreadAffinityMask(hThread, new NativeLong(sameCore? 1L: 2L)); 
     if (spin) { 
      Thread.yield(); 
      while (System.currentTimeMillis() - millisBefore < sleepMillis) 
       ; 
     } else { 
      Thread.sleep(sleepMillis); 
     } 

     long nanosTaken = System.nanoTime() - nanosBefore; 
     long millisTaken = System.currentTimeMillis() - millisBefore; 

     System.out.println("nanosTaken="+nanosTaken); 
     System.out.println("millisTaken="+millisTaken); 
    } 

    public static void main(String[] args) throws InterruptedException { 
     System.out.println("Sleeping, different cores"); 
     testNanoTime(false, false); 
     System.out.println("\nSleeping, same core"); 
     testNanoTime(true, false); 
     System.out.println("\nSpinning, different cores"); 
     testNanoTime(false, true); 
     System.out.println("\nSpinning, same core"); 
     testNanoTime(true, true); 
    } 

    private static final Kernel32Ex kernel = 
     (Kernel32Ex) Native.loadLibrary(Kernel32Ex.class); 

} 

interface Kernel32Ex extends Kernel32 { 
    NativeLong SetThreadAffinityMask(HANDLE hThread, NativeLong dwAffinityMask); 
} 

Nếu bạn nhận được kết quả rất khác nhau tùy thuộc vào lựa chọn lõi (ví dụ 5000ms trên lõi tương tự nhưng 2200ms trên các lõi khác nhau) sẽ gợi ý rằng vấn đề chỉ là sự thay đổi bộ đếm thời gian tự nhiên giữa các lõi.

Nếu bạn nhận được kết quả rất khác so với ngủ so với xoay, có nhiều khả năng là do quản lý nguồn sẽ làm chậm đồng hồ.

Nếu không có trong số bốn kết quả gần 5000 mili giây thì đó có thể là lỗi.