Page 1 of 4 123 ... LastLast
Results 1 to 10 of 39

Thread: Frame latency analysis on Doom 3

  1. #1
    Join Date
    Jun 2011
    Posts
    37

    Lightbulb Frame latency analysis on Doom 3

    As some of you are aware, The Tech Report have been using a new type of analysis on FPS to analyse frame latencies (see http://techreport.com/review/21516/i...e-benchmarking).

    To do this yourself I have devised a methodology (which could be automated) using Doom 3.

    Step 1:
    Record frame timings (I have used the command from the OpenBenchmarking Doom3 Test Profile). The important bit is the com_speeds flag:

    Code:
    ./doom3 +exec doom3-pts.cfg +set sys_VideoRam 512MB +set r_mode -1 +timedemoquit demo1 +set com_speeds 1 > doom3.log
    Step 2:
    Parse log file using this Python script:
    Code:
    import re
    
    # Compile reg exp
    re1='.*?'	    # Non-greedy match on filler
    re2='(\\d+)'	# Integer Number 1
    r = re.compile(re1+re2+re1+re2+re1+re2+re1+re2+re1+re2,re.IGNORECASE|re.DOTALL)
    
    # Open log file
    frames = []
    f = open('doom3.log')
    for line in f.readlines():
        if line.startswith('frame:'):
            m = r.search(line)
            if m:
                frames.append( {'com_frameNumber': int(m.group(1)),
                                'com_frameMsec':   int(m.group(2)), 
                                'time_gameFrame':  int(m.group(3)), 
                                'time_frontend':   int(m.group(4)), 
                                'time_backend':    int(m.group(5))} )
    f.close()
    
    # Write to data file
    f = open('data.csv', 'w')
    f.write('Frame,FrameTime\n')
    for frame in frames:
        # Skip first frame
        if frame['com_frameNumber'] == 0:
            continue
        f.write('%i,%i\n' % (frame['com_frameNumber'], frame['com_frameMsec']))
    f.close()
    Step 3:
    Use this R script on resulting csv file:
    Code:
    dat <- read.csv("data.csv",header=T,colClasses=c("integer","numeric"))
    summary(dat)
    
    # Progression of frame times
    plot(dat, type='n', xlab="Frame number", 
        ylab="Frame time in ms (lower is better)")
    lines(dat)
    
    # Average fps
    max(dat$Frame)*1000/sum(dat$FrameTime)
    
    # Percentiles
    # It's the point below which 99% of all frames have been rendered. 
    # We're simply excluding the last 1% of frames, many of them potential outliers, 
    # to get a sense of overall smoothness. 
    quantile(dat$FrameTime, .99) 
    
    # Frame latencies by percentile
    p <- seq(0, 1, length.out=1000)^(1/3)
    quan <- data.frame(q = quantile(dat$FrameTime, probs = p), prob = p)
    plot(quan$prob, quan$q, type='n', xaxt='n', xlim=c(0.5,1),
      xlab="Proportion of frames rendered", ylab="Frame time in ms (lower is better)")
    axis(1, at=seq(0,1,by=.05), labels=paste(100*seq(0,1,by=.05), "%") )
    lines(quan$prob, quan$q)
    
    # Time spent beyond 50 ms
    sum(subset(dat,FrameTime>50)$FrameTime)
    
    # Time spent beyond 16.7 ms
    sum(subset(dat,FrameTime>16.7)$FrameTime)

    Example of resulting images:



  2. #2

    Default

    I wasn't aware of com_speeds and thanks for the script as reference, I'll take a look into it for supporting test profiles with com_speeds and then having PTS-internal infrastructure for handling that parsing and shoving it into line graph.

  3. #3
    Join Date
    Jun 2011
    Posts
    37

    Default

    Not only the graphs are important but also the values which are calculated in the R script:

    - Average fps (not important for latency analysis)
    - 99% Percentile
    - Time spent beyond 50 ms
    - Time spent beyond 16.7 ms

    PS. Please note that the frametime for the first frame was so high, I ignored it (3.5 seconds)
    Last edited by thofke; 11-05-2012 at 08:59 AM.

  4. #4
    Join Date
    Feb 2008
    Location
    Linuxland
    Posts
    4,987

    Default

    Very nice. Looking forward to seeing latency articles.

  5. #5
    Join Date
    Jun 2011
    Posts
    37

    Default

    Note that this does not measure input-to-output latency, but the latency between consecutive frames.

    Maybe it could be called jitter analysis, as you analyse the undesired deviation from a certain periodic frame rate.

    This article describes better than the previous mentioned article what is possible using this method: http://techreport.com/review/23246/i...ith-today-cpus
    Last edited by thofke; 11-05-2012 at 12:47 PM.

  6. #6

    Default

    Hi. Excellent.

    I ran doom3 with ./doom3 +exec +set sys_VideoRam 512MB +set r_mode -1 +timedemoquit demo1 +set com_speeds 1 > doom3.log

    Maybe a vsynced version, normal time, would be better for jitter measurement. So one should look into that first. And probably remove videoram limit etc.

    Here is my doom3.log

    Peace Be With You.

  7. #7
    Join Date
    Jun 2012
    Posts
    335

    Default

    Quote Originally Posted by thofke View Post
    Note that this does not measure input-to-output latency, but the latency between consecutive frames.

    Maybe it could be called jitter analysis, as you analyse the undesired deviation from a certain periodic frame rate.

    This article describes better than the previous mentioned article what is possible using this method: http://techreport.com/review/23246/i...ith-today-cpus
    Yes yes yes; THIS is how benchmarking is supposed to be done. That was one of Techreports best articles ever.

    But its a bit worrying that an older game like Doom3 has so many latency spikes; eyeballing the graph, the average frame latency looks to be about 20ms or so, indicating significant frame skipping...

  8. #8
    Join Date
    Jun 2011
    Posts
    37

    Default

    Now we can compare.

    Average fps:
    42.37472 (me)
    61.15589 (you)


    Green is your machine, red is mine.


    Striking here is that you have a higher average fps, but my machine has a lower frame time at the far right of the graph.

    That is also visible in the 99th percentile number:
    99% of your frames are drawn in 52.08ms or less, whereas my machine has drawn 99% of the frames in 42ms or less. I would say that my machine has less jitter.

  9. #9

    Default

    The tail (of repeating pattern), running doom3 normally with just +set com_speeds 1 > doom3.log

    frame:7700 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7701 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7702 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7703 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7704 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7705 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7706 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7707 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7708 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7709 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7710 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7711 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7712 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7713 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7714 all: 17 gfr: 0 rf: 0 bk: 16
    frame:7715 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7716 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7717 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7718 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7719 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7720 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7721 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7722 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7723 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7724 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7725 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7726 all: 16 gfr: 0 rf: 1 bk: 15
    frame:7727 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7728 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7729 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7730 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7731 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7732 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7733 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7734 all: 17 gfr: 0 rf: 0 bk: 16
    frame:7735 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7736 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7737 all: 17 gfr: 0 rf: 1 bk: 15
    frame:7738 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7739 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7740 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7741 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7742 all: 17 gfr: 0 rf: 0 bk: 14
    frame:7743 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7744 all: 16 gfr: 0 rf: 1 bk: 15
    frame:7745 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7746 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7747 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7748 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7749 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7750 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7751 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7752 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7753 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7754 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7755 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7756 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7757 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7758 all: 17 gfr: 0 rf: 0 bk: 16
    frame:7759 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7760 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7761 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7762 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7763 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7764 all: 17 gfr: 0 rf: 0 bk: 16
    frame:7765 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7766 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7767 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7768 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7769 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7770 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7771 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7772 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7773 all: 17 gfr: 0 rf: 1 bk: 15
    frame:7774 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7775 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7776 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7777 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7778 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7779 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7780 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7781 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7782 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7783 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7784 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7785 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7786 all: 16 gfr: 0 rf: 0 bk: 16
    frame:7787 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7788 all: 17 gfr: 0 rf: 0 bk: 16
    frame:7789 all: 16 gfr: 0 rf: 0 bk: 15
    frame:7790 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7791 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7792 all: 16 gfr: 0 rf: 1 bk: 15
    frame:7793 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7794 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7795 all: 16 gfr: 0 rf: 1 bk: 15
    frame:7796 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7797 all: 17 gfr: 0 rf: 0 bk: 15
    frame:7798 all: 16 gfr: 0 rf: 1 bk: 15
    frame:7799 all: 17 gfr: 0 rf: 0 bk: 15

    Framerate is quite smooth. This in 1280x1024, nvidia, 2xaniso, vsync, 2xAA, lowjitter kernel, core2duo @ 2.5ghz.

    Peace Be With You.

  10. #10
    Join Date
    Jun 2011
    Posts
    37

    Default

    That means that every frame is taking 1/60 seconds (or 16.7ms). If you never experience a stuttering frame (i.e. higher than 16.7ms per frame), then maybe the demo is not a good benchmark or maybe is the demo very hard on resources?

Tags for this Thread

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •