Announcement

Collapse
No announcement yet.

Frame latency analysis on Doom 3

Collapse
X
  • Filter
  • Time
  • Show
Clear All
new posts

  • 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
    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.
    Michael Larabel
    http://www.michaellarabel.com/

    Comment


    • #3
      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, 08:59 AM.

      Comment


      • #4
        Very nice. Looking forward to seeing latency articles.

        Comment


        • #5
          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, 12:47 PM.

          Comment


          • #6
            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.

            Comment


            • #7
              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...

              Comment


              • #8
                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.

                Comment


                • #9
                  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.

                  Comment


                  • #10
                    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?

                    Comment


                    • #11
                      PS: If you try +playdemo you will see that the demo is recorded with jitter. So it`s like watching a poor youtube stream. Thus useless for jitter benchmark. If a demo is to be used, it needs to be generated without jitter.

                      Peace Be With You.

                      Comment


                      • #12
                        Most likely the jitter is in your brain. Why don't you record one and compare?

                        Comment


                        • #13
                          Originally posted by Kano View Post
                          Most likely the jitter is in your brain. Why don't you record one and compare?
                          Why would you make such a non-constructive comment? If you do not have anything to add, please refrain from commenting.

                          Originally posted by Wikipedia
                          Jitter is the undesired deviation from true periodicity of an assumed periodic signal in electronics and telecommunications, often in relation to a reference clock source. Jitter may be observed in characteristics such as the frequency of successive pulses, the signal amplitude, or phase of periodic signals.
                          If you look at the frame rate of a game as a periodic signal or as successive pulses from the previous definition, any deviation from that periodicity could be called jitter.
                          Last edited by thofke; 11-06-2012, 04:11 AM.

                          Comment


                          • #14
                            Well think about a game scene, why would it be possible that you can record jitter? timedemo plays the same content just in the max possible speed, when you disable vsync in the video driver (nv 300+ has vsync active by default) then you get higher rates than 60 fps. But when it is played at normal speed then he say it has jitter - not that i laugh. Even when you record the movement (something like that is in the demo) with less than 60 hz then it can only be a bit jumpy but never jitter as the same content can not be played with less than 60 fps when it would have got that speed. He is just weird and sees everywhere jitter where nothing is. It is definitely NOT the question if a frame takes too long to render.

                            Comment


                            • #15
                              If you look at the graphs from page 1, you see that there are frames which take more than 100ms to render. This is unwanted behaviour and corresponds to a lowly 10 FPS or less (!). All standard benchmark software masks this behaviour by the fact that the frames per second metric averages out those long frames. I suppose we agree on the fact that this method adds a lot of useful information about how smooth a game runs.

                              How would you call this new type of analysis then?

                              Comment

                              Working...
                              X