[core] Measure intended latency and old latency side by side.

Add a joined histogram measuremement to compare old/new histogram
outputs.

core/src/main/java/com/yahoo/ycsb/Client.java

@@ -275,7 +275,7 @@ class ClientThread extends Thread
 
 		try
 		{
-		    _measurements.setStartTimeNs(0);
+		    _measurements.setIntendedStartTimeNs(0);
 			_db.cleanup();
 		}
 		catch (DBException e)
@@ -300,7 +300,7 @@ class ClientThread extends Thread
             long deadline = startTimeNanos + _opsdone*_targetOpsTickNs;
             sleepUntil(deadline);
             if(_measureFromIntendedDeadline)
-                _measurements.setStartTimeNs(deadline);
+                _measurements.setIntendedStartTimeNs(deadline);
         }
     }
     

core/src/main/java/com/yahoo/ycsb/DBWrapper.java

@@ -69,10 +69,11 @@ public class DBWrapper extends DB
 	 */
 	public void cleanup() throws DBException
 	{
-    long st=_measurements.startTimeNs();
+    long ist=_measurements.getIntendedtartTimeNs();
+    long st = System.nanoTime();
 		_db.cleanup();
     long en=System.nanoTime();
-    _measurements.measure("CLEANUP", (int)((en-st)/1000));
+    measure(ist, st, en);
 	}
 
 	/**
@@ -86,11 +87,12 @@ public class DBWrapper extends DB
 	 */
 	public int read(String table, String key, Set<String> fields, HashMap<String,ByteIterator> result)
 	{
-		long st=_measurements.startTimeNs();
-		int res=_db.read(table,key,fields,result);
+	    long ist=_measurements.getIntendedtartTimeNs();
+	    long st = System.nanoTime();
+	    int res=_db.read(table,key,fields,result);
 		long en=System.nanoTime();
-		_measurements.measure("READ",(int)((en-st)/1000));
-		_measurements.reportReturnCode("READ",res);
+		measure(ist, st, en);
+	    _measurements.reportReturnCode("READ",res);
 		return res;
 	}
 
@@ -106,13 +108,19 @@ public class DBWrapper extends DB
 	 */
 	public int scan(String table, String startkey, int recordcount, Set<String> fields, Vector<HashMap<String,ByteIterator>> result)
 	{
-		long st=_measurements.startTimeNs();
-		int res=_db.scan(table,startkey,recordcount,fields,result);
+	    long ist=_measurements.getIntendedtartTimeNs();
+	    long st = System.nanoTime();
+	    int res=_db.scan(table,startkey,recordcount,fields,result);
 		long en=System.nanoTime();
-		_measurements.measure("SCAN",(int)((en-st)/1000));
-		_measurements.reportReturnCode("SCAN",res);
+		measure(ist, st, en);
+	    _measurements.reportReturnCode("SCAN",res);
 		return res;
 	}
+
+    private void measure(long intendedStartTimeNanos, long startTimeNanos, long endTimeNanos) {
+        _measurements.measure("CLEANUP", (int)((endTimeNanos-startTimeNanos)/1000));
+	    _measurements.measureIntended("CLEANUP", (int)((endTimeNanos-intendedStartTimeNanos)/1000));
+    }
 	
 	/**
 	 * Update a record in the database. Any field/value pairs in the specified values HashMap will be written into the record with the specified
@@ -125,10 +133,11 @@ public class DBWrapper extends DB
 	 */
 	public int update(String table, String key, HashMap<String,ByteIterator> values)
 	{
-		long st=_measurements.startTimeNs();
+	    long ist=_measurements.getIntendedtartTimeNs();
+	    long st = System.nanoTime();
 		int res=_db.update(table,key,values);
 		long en=System.nanoTime();
-		_measurements.measure("UPDATE",(int)((en-st)/1000));
+		measure(ist, st, en);
 		_measurements.reportReturnCode("UPDATE",res);
 		return res;
 	}
@@ -144,10 +153,11 @@ public class DBWrapper extends DB
 	 */
 	public int insert(String table, String key, HashMap<String,ByteIterator> values)
 	{
-		long st=_measurements.startTimeNs();
+	    long ist=_measurements.getIntendedtartTimeNs();
+	    long st = System.nanoTime();
 		int res=_db.insert(table,key,values);
 		long en=System.nanoTime();
-		_measurements.measure("INSERT",(int)((en-st)/1000));
+		measure(ist, st, en);
 		_measurements.reportReturnCode("INSERT",res);
 		return res;
 	}
@@ -161,10 +171,11 @@ public class DBWrapper extends DB
 	 */
 	public int delete(String table, String key)
 	{
-		long st=_measurements.startTimeNs();
+	    long ist=_measurements.getIntendedtartTimeNs();
+	    long st = System.nanoTime();
 		int res=_db.delete(table,key);
 		long en=System.nanoTime();
-		_measurements.measure("DELETE",(int)((en-st)/1000));
+		measure(ist, st, en);
 		_measurements.reportReturnCode("DELETE",res);
 		return res;
 	}

core/src/main/java/com/yahoo/ycsb/measurements/Measurements.java

@@ -18,7 +18,6 @@
 package com.yahoo.ycsb.measurements;
 
 import java.io.IOException;
-import java.util.HashMap;
 import java.util.Properties;
 import java.util.concurrent.ConcurrentHashMap;
 
@@ -57,8 +56,9 @@ public class Measurements
 		return singleton;
 	}
 
-	final ConcurrentHashMap<String,OneMeasurement> data;
-	int measurementType=0;
+    final ConcurrentHashMap<String,OneMeasurement> opToMesurementMap;
+    final ConcurrentHashMap<String,OneMeasurement> opToIntendedMesurementMap;
+	final int measurementType;
 
 	private Properties _props;
 	
@@ -67,7 +67,8 @@ public class Measurements
        */
 	public Measurements(Properties props)
 	{
-		data=new ConcurrentHashMap<String,OneMeasurement>();
+        opToMesurementMap=new ConcurrentHashMap<String,OneMeasurement>();
+        opToIntendedMesurementMap=new ConcurrentHashMap<String,OneMeasurement>();
 		
 		_props=props;
 		
@@ -79,10 +80,14 @@ public class Measurements
 		else if (mTypeString.equals("hdrhistogram"))
 		{
             measurementType=1;
+        }
+		else if (mTypeString.equals("hdrhistogram+buckethistogram"))
+        {
+            measurementType=2;
         }
 		else
 		{
-		    measurementType=2;
+		    measurementType=3;
 		}
 	}
 	
@@ -94,7 +99,10 @@ public class Measurements
             return new OneMeasurementHistogram(name, _props);
         case 1:
             return new OneMeasurementHdrHistogram(name, _props);
-
+        case 2:
+            return new TwoInOneMeasurement(name, 
+                    new OneMeasurementHdrHistogram("Hdr"+name, _props), 
+                    new OneMeasurementHistogram("Bucket"+name, _props));
         default:
             return new OneMeasurementTimeSeries(name, _props);
         }
@@ -116,31 +124,26 @@ public class Measurements
           return new StartTimeHolder();
       };  
     };
-    public void setStartTimeNs(long time){
+    public void setIntendedStartTimeNs(long time){
         tls.get().time=time;
     }
-    public long startTimeNs(){
+    
+    public long getIntendedtartTimeNs(){
         return tls.get().startTime();
     }
-      /**
-       * Report a single value of a single metric. E.g. for read latency, operation="READ" and latency is the measured value.
-       */
+
+    /**
+     * Report a single value of a single metric. E.g. for read latency, operation="READ" and latency is the measured
+     * value.
+     */
 	public void measure(String operation, int latency)
 	{
-		
 		try
 		{
-			OneMeasurement m = data.get(operation);
-			if(m == null) {
-			    m = constructOneMeasurement(operation);
-			    OneMeasurement oldM = data.putIfAbsent(operation, m);
-			    if(oldM != null)
-			    {
-			        m = oldM;
-			    }
-			}
+			OneMeasurement m = getOpMeasurement(operation);
             m.measure(latency);
 		}
+		// This seems like a terribly hacky way to cover up for a bug in the measurement code
 		catch (java.lang.ArrayIndexOutOfBoundsException e)
 		{
 			System.out.println("ERROR: java.lang.ArrayIndexOutOfBoundsException - ignoring and continuing");
@@ -148,23 +151,59 @@ public class Measurements
 			e.printStackTrace(System.out);
 		}
 	}
+    /**
+     * Report a single value of a single metric. E.g. for read latency, operation="READ" and latency is the measured
+     * value.
+     */
+    public void measureIntended(String operation, int latency)
+    {
+        try
+        {
+            OneMeasurement m = getOpIntendedMeasurement(operation);
+            m.measure(latency);
+        }
+        // This seems like a terribly hacky way to cover up for a bug in the measurement code
+        catch (java.lang.ArrayIndexOutOfBoundsException e)
+        {
+            System.out.println("ERROR: java.lang.ArrayIndexOutOfBoundsException - ignoring and continuing");
+            e.printStackTrace();
+            e.printStackTrace(System.out);
+        }
+    }
 
+    private OneMeasurement getOpMeasurement(String operation) {
+        OneMeasurement m = opToMesurementMap.get(operation);
+        if(m == null)
+        {
+            m = constructOneMeasurement(operation);
+            OneMeasurement oldM = opToMesurementMap.putIfAbsent(operation, m);
+            if(oldM != null)
+            {
+                m = oldM;
+            }
+        }
+        return m;
+    }
+    private OneMeasurement getOpIntendedMeasurement(String operation) {
+        OneMeasurement m = opToIntendedMesurementMap.get(operation);
+        if(m == null)
+        {
+            m = constructOneMeasurement("Intended-"+operation);
+            OneMeasurement oldM = opToIntendedMesurementMap.putIfAbsent(operation, m);
+            if(oldM != null)
+            {
+                m = oldM;
+            }
+        }
+        return m;
+    }
       /**
        * Report a return code for a single DB operaiton.
        */
 	public void reportReturnCode(String operation, int code)
 	{
-		if (!data.containsKey(operation))
-		{
-			synchronized(this)
-			{
-				if (!data.containsKey(operation))
-				{
-					data.put(operation,constructOneMeasurement(operation));
-				}
-			}
-		}
-		data.get(operation).reportReturnCode(code);
+	    OneMeasurement m = getOpMeasurement(operation);
+		m.reportReturnCode(code);
 	}
 	
   /**
@@ -175,10 +214,14 @@ public class Measurements
    */
   public void exportMeasurements(MeasurementsExporter exporter) throws IOException
   {
-    for (OneMeasurement measurement : data.values())
-    {
-      measurement.exportMeasurements(exporter);
-    }
+      for (OneMeasurement measurement : opToMesurementMap.values())
+      {
+        measurement.exportMeasurements(exporter);
+      }
+      for (OneMeasurement measurement : opToIntendedMesurementMap.values())
+      {
+        measurement.exportMeasurements(exporter);
+      }
   }
 	
       /**
@@ -187,11 +230,14 @@ public class Measurements
 	public synchronized String getSummary()
 	{
 		String ret="";
-		for (OneMeasurement m : data.values())
+		for (OneMeasurement m : opToMesurementMap.values())
 		{
 			ret+=m.getSummary()+" ";
 		}
-		
+		for (OneMeasurement m : opToIntendedMesurementMap.values())
+        {
+            ret+=m.getSummary()+" ";
+        }
 		return ret;
 	}
 }

core/src/main/java/com/yahoo/ycsb/measurements/OneMeasurementHdrHistogram.java

@@ -24,16 +24,15 @@ import java.util.Properties;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.atomic.AtomicInteger;
 
-import org.HdrHistogram.ConcurrentHistogram;
 import org.HdrHistogram.Histogram;
 import org.HdrHistogram.Recorder;
 
 import com.yahoo.ycsb.measurements.exporter.MeasurementsExporter;
 
 /**
- * Take measurements and maintain a histogram of a given metric, such as READ LATENCY.
+ * Take measurements and maintain a HdrHistogram of a given metric, such as READ LATENCY.
  * 
- * @author cooperb
+ * @author nitsanw
  *
  */
 public class OneMeasurementHdrHistogram extends OneMeasurement {
@@ -69,7 +68,7 @@ public class OneMeasurementHdrHistogram extends OneMeasurement {
 
     /**
      * It appears latency is reported in micros.
-     * Using {@link ConcurrentHistogram} to support concurrent updates to histogram.
+     * Using {@link Recorder} to support concurrent updates to histogram.
      * 
      * @see com.yahoo.ycsb.OneMeasurement#measure(int)
      */
@@ -84,14 +83,8 @@ public class OneMeasurementHdrHistogram extends OneMeasurement {
      */
     @Override
     public void exportMeasurements(MeasurementsExporter exporter) throws IOException {
-        Histogram lastIntervalHistogram = histogram.getIntervalHistogram();
-        // add this to the total time histogram.
-        if (totalHistogram == null) {
-            totalHistogram = lastIntervalHistogram; 
-        }
-        else {
-            totalHistogram.add(lastIntervalHistogram);
-        }
+        // accumulate the last interval which was not caught by status thread
+        getIntervalHistogramAndAccumulate();
         exporter.write(getName(), "Operations", totalHistogram.getTotalCount());
         exporter.write(getName(), "AverageLatency(us)", totalHistogram.getMean());
         exporter.write(getName(), "MinLatency(us)", totalHistogram.getMinValue());
@@ -107,18 +100,12 @@ public class OneMeasurementHdrHistogram extends OneMeasurement {
 
     /**
      * This is called periodically from the StatusThread. There's a single StatusThread per Client process.
+     * We optionally serialize the interval to log on this opportunity.
      * @see com.yahoo.ycsb.measurements.OneMeasurement#getSummary()
      */
     @Override
     public String getSummary() {
-        Histogram intervalHistogram = histogram.getIntervalHistogram();
-        // add this to the total time histogram.
-        if (totalHistogram == null) {
-            totalHistogram = intervalHistogram; 
-        }
-        else {
-            totalHistogram.add(intervalHistogram);
-        }
+        Histogram intervalHistogram = getIntervalHistogramAndAccumulate();
         DecimalFormat d = new DecimalFormat("#.##");
         return "[" + getName() + 
                 ": Count=" + intervalHistogram.getTotalCount() + 
@@ -131,4 +118,16 @@ public class OneMeasurementHdrHistogram extends OneMeasurement {
                 ", 99.99=" + d.format(intervalHistogram.getValueAtPercentile(99.99)) +"]";
     }
 
+    private Histogram getIntervalHistogramAndAccumulate() {
+        Histogram intervalHistogram = histogram.getIntervalHistogram();
+        // add this to the total time histogram.
+        if (totalHistogram == null) {
+            totalHistogram = intervalHistogram; 
+        }
+        else {
+            totalHistogram.add(intervalHistogram);
+        }
+        return intervalHistogram;
+    }
+
 }

core/src/main/java/com/yahoo/ycsb/measurements/TwoInOneMeasurement.java

+/**                                                                                                                                                                                
+ * Copyright (c) 2010 Yahoo! Inc. All rights reserved.                                                                                                                             
+ *                                                                                                                                                                                 
+ * Licensed under the Apache License, Version 2.0 (the "License"); you                                                                                                             
+ * may not use this file except in compliance with the License. You                                                                                                                
+ * may obtain a copy of the License at                                                                                                                                             
+ *                                                                                                                                                                                 
+ * http://www.apache.org/licenses/LICENSE-2.0                                                                                                                                      
+ *                                                                                                                                                                                 
+ * Unless required by applicable law or agreed to in writing, software                                                                                                             
+ * distributed under the License is distributed on an "AS IS" BASIS,                                                                                                               
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or                                                                                                                 
+ * implied. See the License for the specific language governing                                                                                                                    
+ * permissions and limitations under the License. See accompanying                                                                                                                 
+ * LICENSE file.                                                                                                                                                                   
+ */
+
+package com.yahoo.ycsb.measurements;
+
+import java.io.IOException;
+
+import org.HdrHistogram.Recorder;
+
+import com.yahoo.ycsb.measurements.exporter.MeasurementsExporter;
+
+/**
+ * delegates to 2 measuremement instances.
+ * @author nitsanw
+ *
+ */
+public class TwoInOneMeasurement extends OneMeasurement {
+    final OneMeasurement thing1,thing2;
+    public TwoInOneMeasurement(String name, OneMeasurement thing1,OneMeasurement thing2) {
+        super(name);
+        this.thing1 = thing1;
+        this.thing2 = thing2;
+    }
+
+    /**
+     * No need for synchronization, using CHM to deal with that
+     * 
+     * @see com.yahoo.ycsb.OneMeasurement#reportReturnCode(int)
+     */
+    public void reportReturnCode(int code) {
+        thing1.reportReturnCode(code);
+    }
+
+    /**
+     * It appears latency is reported in micros.
+     * Using {@link Recorder} to support concurrent updates to histogram.
+     * 
+     * @see com.yahoo.ycsb.OneMeasurement#measure(int)
+     */
+    public void measure(int latencyInMicros) {
+        thing1.measure(latencyInMicros);
+        thing2.measure(latencyInMicros);
+    }
+
+    /**
+     * This is called from a main thread, on orderly termination.
+     * 
+     * @see com.yahoo.ycsb.measurements.OneMeasurement#exportMeasurements(com.yahoo.ycsb.measurements.exporter.MeasurementsExporter)
+     */
+    @Override
+    public void exportMeasurements(MeasurementsExporter exporter) throws IOException {
+        thing1.exportMeasurements(exporter);
+        thing2.exportMeasurements(exporter);
+    }
+
+    /**
+     * This is called periodically from the StatusThread. There's a single StatusThread per Client process.
+     * We optionally serialize the interval to log on this opportunity.
+     * @see com.yahoo.ycsb.measurements.OneMeasurement#getSummary()
+     */
+    @Override
+    public String getSummary() {
+        return thing1.getSummary() + "\n" + thing2.getSummary();
+    }
+}

core/src/main/java/com/yahoo/ycsb/workloads/CoreWorkload.java

@@ -18,6 +18,7 @@
 package com.yahoo.ycsb.workloads;
 
 import java.util.Properties;
+
 import com.yahoo.ycsb.*;
 import com.yahoo.ycsb.generator.CounterGenerator;
 import com.yahoo.ycsb.generator.DiscreteGenerator;
@@ -687,8 +688,9 @@ public class CoreWorkload extends Workload
 		HashMap<String,ByteIterator> cells =
 		    new HashMap<String,ByteIterator>();
 
-		long st=_measurements.startTimeNs();
-
+		
+		long ist=_measurements.getIntendedtartTimeNs();
+	    long st = System.nanoTime();
 		db.read(table,keyname,fields,cells);
 		
 		db.update(table,keyname,values);
@@ -700,6 +702,7 @@ public class CoreWorkload extends Workload
     }
 
 		_measurements .measure("READ-MODIFY-WRITE", (int)((en-st)/1000));
+		_measurements .measureIntended("READ-MODIFY-WRITE", (int)((en-ist)/1000));
 	}
 	
 	public void doTransactionScan(DB db)