[PATCH 0/1] Disk io measurements for build statistics

[PATCH 0/1] Disk io measurements for build statistics

[Beth Flanagan]

This commit adds disk-io statistics functionality on a build
and per-task basis. I've also started drying it up some.

We pull measurements for whatever partition TMPDIR exists on.
We pull /proc/diskstats for every task and the entire build and collect
I do no analysis in this, leaving that for the end user. 
The following changes since commit 5fbac72eb8c3cddf10876cf007aff54180c7264e:

  multilib: Use BPN instead of PN for style like lib${PN} (2011-08-03 18:07:25 +0100)

are available in the git repository at:
  git://git.pokylinux.org/poky-contrib eflanagan/disk-io-stats
  http://git.pokylinux.org/cgit.cgi/poky-contrib/log/?h=eflanagan/disk-io-stats

Beth Flanagan (1):
  buildstats.bbclass: Adding disk io measurement

 meta/classes/buildstats.bbclass |  220 +++++++++++++++++++++++++--------------
 1 files changed, 142 insertions(+), 78 deletions(-)

[PATCH 0/1] Disk io measurements for build statistics

[Beth Flanagan]

Resubmitting with task end time put back in. This should allow us
to plot ${PN} tasks along an axis with various disk io to give
us a better idea where disk thrash is occurring

This commit adds disk-io statistics functionality on a build
and per-task basis. I've also started drying it up some.

We pull measurements for whatever partition TMPDIR exists on.
We pull /proc/diskstats for every task and the entire build and collect
I do no analysis in this, leaving that for the end user. 

The following changes since commit 5561aaad28ed6db6d962f88db32814043044731f:

  eglibc: Fix patch merge breakage (2011-08-04 15:41:19 +0100)

are available in the git repository at:
  git://git.pokylinux.org/poky-contrib eflanagan/disk-io-stats
  http://git.pokylinux.org/cgit.cgi/poky-contrib/log/?h=eflanagan/disk-io-stats

Beth Flanagan (1):
  buildstats.bbclass: Adding disk io measurement

 meta/classes/buildstats.bbclass |  221 +++++++++++++++++++++++++--------------
 1 files changed, 142 insertions(+), 79 deletions(-)

[PATCH 1/1] buildstats.bbclass: Adding disk io measurement

[Beth Flanagan]

This commit adds disk-io statistics functionality on a build
and per-task basis.

It pulls measurements for whatever partition TMPDIR exists on.
This data could be off if SSTATE_DIR and DL_DIR exist on
a different partition/volume.

Notes on what this pulls:

ReadsComp: Total number of reads complete
ReadsMerged: Total number of adjacent reads merged
SectRead: Total number of sectors read
TimeReads: Total number of m/s spent reading
WritesComp: Total number of writes completed
SectWrite: Total number of sectors written
TimeWrite: Total number of m/s spent writing
IOinProgress: Total amount of IO in progress at the time of
              we look at /proc/diskstats.
TimeIO: Total number of m/s spent doing IO
WTimeIO: Weighted time doing I/O. From iostats.txt:

"This field is incremented at each I/O start, I/O completion, I/O
 merge, or read of these stats by the number of I/Os in progress
 (field 9) times the number of milliseconds spent doing I/O since the
 last update of this field.  This can provide an easy measure of both
 I/O completion time and the backlog that may be accumulating."

Signed-off-by: Beth Flanagan <elizabeth.flanagan@intel.com>
---
 meta/classes/buildstats.bbclass |  221 +++++++++++++++++++++++++--------------
 1 files changed, 142 insertions(+), 79 deletions(-)

diff --git a/meta/classes/buildstats.bbclass b/meta/classes/buildstats.bbclass
index 8077035..3319f68 100644
--- a/meta/classes/buildstats.bbclass
+++ b/meta/classes/buildstats.bbclass
@@ -1,5 +1,6 @@
 BUILDSTATS_BASE = ${TMPDIR}/buildstats/
 BNFILE = ${BUILDSTATS_BASE}/.buildname
+DEVFILE = ${BUILDSTATS_BASE}/.device
 
 ################################################################################
 # Build statistics gathering. 
@@ -19,9 +20,79 @@ def get_cputime():
     fields = open("/proc/stat", "r").readline().rstrip().split()[1:]
     return sum(int(field) for field in fields)
 
+def set_bn(e):
+    bn = e.getPkgs()[0] + "-" + bb.data.getVar('MACHINE',e.data, True)
+    try:
+        os.remove(bb.data.getVar('BNFILE', e.data, True))
+    except:
+        pass
+    file = open(bb.data.getVar('BNFILE', e.data, True), "w")
+    file.write(os.path.join(bn, bb.data.getVar('BUILDNAME', e.data, True)))
+    file.close()
+
+def get_bn(e):
+    file = open(bb.data.getVar('BNFILE', e.data, True))
+    bn = file.readline()
+    file.close()
+    return bn
+
+def set_device(e):
+    tmpdir = bb.data.getVar('TMPDIR', e.data, True)
+    try:
+        os.remove(bb.data.getVar('DEVFILE', e.data, True))
+    except:
+        pass
+    ############################################################################
+    # We look for the volume TMPDIR lives on. To do all disks would make little 
+    # sense and not give us any particularly useful data. In theory we could do
+    # something like stick DL_DIR on a different partition and this would
+    # throw stats gathering off. The same goes with SSTATE_DIR. However, let's
+    # get the basics in here and work on the cornercases later. 
+    ############################################################################
+    device=os.stat(tmpdir)
+    majordev=os.major(device.st_dev)
+    minordev=os.minor(device.st_dev)
+    for line in open("/proc/diskstats", "r"):
+        if majordev == int(line.split()[0]) and minordev == int(line.split()[1]):
+           rdev=line.split()[2]
+    file = open(bb.data.getVar('DEVFILE', e.data, True), "w")
+    file.write(rdev)
+    file.close()
+    
+def get_device(e):
+    file = open(bb.data.getVar('DEVFILE', e.data, True))
+    device = file.readline()
+    file.close()
+    return device
+
+def get_diskstats(dev):
+    import itertools
+    ############################################################################
+    # For info on what these are, see kernel doc file iostats.txt
+    ############################################################################
+    DSTAT_KEYS = ['ReadsComp', 'ReadsMerged', 'SectRead', 'TimeReads', 'WritesComp', 'SectWrite', 'TimeWrite', 'IOinProgress', 'TimeIO', 'WTimeIO']  
+    for x in open("/proc/diskstats", "r"):
+        if dev in x:
+            diskstats_val = x.rstrip().split()[4:]
+    diskstats = dict(itertools.izip(DSTAT_KEYS, diskstats_val))        
+    return diskstats
+    
+def set_diskdata(var, dev, data):
+    data.setVar(var, get_diskstats(dev))
+
+def get_diskdata(var, dev, data):
+    olddiskdata = data.getVar(var, False)
+    diskdata = {}
+    if olddiskdata is None:
+       return
+    newdiskdata = get_diskstats(dev)
+    for key in olddiskdata.iterkeys():
+        diskdata["Start"+key] = str(int(olddiskdata[key]))        
+        diskdata["End"+key] = str(int(newdiskdata[key]))    
+    return diskdata
+    
 def set_timedata(var, data):
     import time
-
     time = time.time()
     cputime = get_cputime()
     proctime = get_process_cputime(os.getpid())
@@ -42,26 +113,36 @@ def get_timedata(var, data):
         cpuperc = None
     return timediff, cpuperc
     
-##############################################
-# We need to set the buildname to a file since
-# BUILDNAME changes throughout a build
-##############################################
-
-def set_bn(e):
-    bn = e.getPkgs()[0] + "-" + bb.data.getVar('MACHINE',e.data, True)
-    try:
-        os.remove(bb.data.getVar('BNFILE',e.data, True))
-    except:
-        pass
-    file = open(bb.data.getVar('BNFILE',e.data, True), "w")
-    file.write(os.path.join(bn, bb.data.getVar('BUILDNAME', e.data, True)))
-    file.close()
-
-def get_bn(e):
-    file = open(bb.data.getVar('BNFILE',e.data, True))
-    bn = file.readline()
+def write_task_data(status, logfile, dev, e):
+    bn = get_bn(e)
+    bsdir = os.path.join(bb.data.getVar('BUILDSTATS_BASE', e.data, True), bn)
+    taskdir = os.path.join(bsdir, bb.data.expand("${PF}", e.data))
+    file = open(os.path.join(logfile), "a")
+    timedata = get_timedata("__timedata_task", e.data)
+    if timedata:
+        elapsedtime, cpu = timedata
+        file.write(bb.data.expand("${PF}: %s: Elapsed time: %0.2f seconds \n" %
+                                 (e.task, elapsedtime), e.data))
+        if cpu:
+            file.write("CPU usage: %0.1f%% \n" % cpu)
+    ############################################################################
+    # Here we gather up disk data. In an effort to avoid lying with stats
+    # I do a bare minimum of analysis of collected data.
+    # The simple fact is, doing disk io collection on a per process basis
+    # without effecting build time would be difficult.
+    # For the best information, running things with BB_TOTAL_THREADS = "1"
+    # would return accurate per task results.
+    ############################################################################
+    diskdata = get_diskdata("__diskdata_task", dev, e.data)
+    if diskdata:
+        for key in sorted(diskdata.iterkeys()):
+            file.write(key + ": " + diskdata[key] + "\n")
+    if status is "passed":
+	    file.write("Status: PASSED \n")
+    else:
+        file.write("Status: FAILED \n")
+    file.write("Ended: %0.2f \n" % time.time())
     file.close()
-    return bn
 
 python run_buildstats () {
     import bb.build
@@ -70,21 +151,25 @@ python run_buildstats () {
     import time, subprocess, platform
 
     if isinstance(e, bb.event.BuildStarted):
-        ##############################################
+        ########################################################################
         # at first pass make the buildstats heriarchy and then
         # set the buildname
-        ##############################################
+        ########################################################################
         try:
             bb.mkdirhier(bb.data.getVar('BUILDSTATS_BASE', e.data, True))
         except:
             pass
         set_bn(e)
         bn = get_bn(e)
+        set_device(e)
+        device = get_device(e)
+        
         bsdir = os.path.join(bb.data.getVar('BUILDSTATS_BASE', e.data, True), bn)
         try:
             bb.mkdirhier(bsdir)
         except:
             pass
+        set_diskdata("__diskdata_build", device, e.data)
         set_timedata("__timedata_build", e.data)
         build_time = os.path.join(bsdir, "build_stats")
         # write start of build into build_time
@@ -99,27 +184,36 @@ python run_buildstats () {
         file.close()
                 
     elif isinstance(e, bb.event.BuildCompleted):
-        bn=get_bn(e)
-        timedata = get_timedata("__timedata_build", e.data)
-        if not timedata:
-            return
-        time, cpu = timedata
+        bn = get_bn(e)
+        dev = get_device(e)
         bsdir = os.path.join(bb.data.getVar('BUILDSTATS_BASE', e.data, True), bn)
+        taskdir = os.path.join(bsdir, bb.data.expand("${PF}", e.data))
         build_time = os.path.join(bsdir, "build_stats")
-        # write end of build and cpu used into build_time
         file = open(build_time, "a")
-        file.write("Elapsed time: %0.2f seconds \n" % (time))
-        if cpu:
-            file.write("CPU usage: %0.1f%% \n" % cpu)
+        ########################################################################
+        # Write build statistics for the build
+        ########################################################################
+        timedata = get_timedata("__timedata_build", e.data)
+        if timedata:
+            time, cpu = timedata
+            # write end of build and cpu used into build_time
+            file = open(build_time, "a")
+            file.write("Elapsed time: %0.2f seconds \n" % (time))
+            if cpu:
+                file.write("CPU usage: %0.1f%% \n" % cpu)
+        diskio = get_diskdata("__diskdata_build", dev, e.data)
+        if diskio:
+            for key in sorted(diskio.iterkeys()):
+                file.write(key + ": " + diskio[key] + "\n")
         file.close()
 
-
     if isinstance(e, bb.build.TaskStarted):
-        bn=get_bn(e)
-        set_timedata("__timedata_task", e.data)
-        
+        bn = get_bn(e)
+        device = get_device(e)
         bsdir = os.path.join(bb.data.getVar('BUILDSTATS_BASE', e.data, True), bn)
         taskdir = os.path.join(bsdir, bb.data.expand("${PF}", e.data))
+        set_diskdata("__diskdata_task", device, e.data)
+        set_timedata("__timedata_task", e.data)
         try:
             bb.mkdirhier(taskdir)
         except:
@@ -131,29 +225,13 @@ python run_buildstats () {
         file.close()
 
     elif isinstance(e, bb.build.TaskSucceeded):
-        bn=get_bn(e)
-        timedata = get_timedata("__timedata_task", e.data)
-        if not timedata:
-            return
-        elapsedtime, cpu = timedata
+        bn = get_bn(e)
+        device = get_device(e)
         bsdir = os.path.join(bb.data.getVar('BUILDSTATS_BASE', e.data, True), bn)
         taskdir = os.path.join(bsdir, bb.data.expand("${PF}", e.data))
-        file = open(os.path.join(taskdir, e.task), "a")
-        file.write(bb.data.expand("${PF}: %s: Elapsed time: %0.2f seconds \n" %
-                               (e.task, elapsedtime), e.data))
-        file.write("Ended: %0.2f \n" % time.time())
-        if cpu:
-            file.write("CPU usage: %0.1f%% \n" % cpu)
-    	
-    	file.write("Status: PASSED")
-        file.close()
-
-        ##############################################
-        # Alot of metric gathering occurs here. 
-        # Reminder: I stripped out some in process stuff here
-        ##############################################
-
+        write_task_data("passed", os.path.join(taskdir, e.task), device, e)
         if e.task == "do_rootfs":
+            bsdir = os.path.join(bb.data.getVar('BUILDSTATS_BASE', e.data, True), bn)
             bs=os.path.join(bsdir, "build_stats")
             file = open(bs,"a") 
             rootfs = bb.data.getVar('IMAGE_ROOTFS', e.data, True)
@@ -162,36 +240,21 @@ python run_buildstats () {
             file.close()
 
     elif isinstance(e, bb.build.TaskFailed):
-        bn=get_bn(e)
-        timedata = get_timedata("__timedata_task", e.data)
-        if not timedata:
-            return
-        time, cpu = timedata
+        bn = get_bn(e)
+        device = get_device(e)
         bsdir = os.path.join(bb.data.getVar('BUILDSTATS_BASE', e.data, True), bn)
         taskdir = os.path.join(bsdir, bb.data.expand("${PF}", e.data))
-        ##############################################
-        # If the task fails dump the regular data. 
-        # fgrep -R "FAILED" <bsdir> 
-        # will grep all the events that failed. 
-        ##############################################
-        file = open(os.path.join(taskdir, e.task), "a")
-        file.write(bb.data.expand("${PF}: %s: Elapsed time: %0.2f seconds \n" %
-                               (e.task, time), e.data))
-        if cpu:
-            file.write("CPU usage: %0.1f%% \n" % cpu)
-        file.write("Status: FAILED")
-        file.close()
-        ##############################################
-        # Lets make things easier and tell people where the build failed in build_status
-        # We do this here because BuildCompleted triggers no matter what the status of the
-        # build actually is
-        ##############################################
+        write_task_data("failed", os.path.join(taskdir, e.task), device, e)
+        ########################################################################
+        # Lets make things easier and tell people where the build failed in 
+        # build_status. We do this here because BuildCompleted triggers no 
+        # matter what the status of the build actually is
+        ########################################################################
         build_status = os.path.join(bsdir, "build_stats")
         file = open(build_status,"a")
         file.write(bb.data.expand("Failed at: ${PF} at task: %s \n" % e.task, e.data))
         file.close()
-
+        
 }
 
 addhandler run_buildstats
-
-- 
1.7.1