Response latencies are measured in microseconds

NoSQL databases are capable on sub-millisecond latencies and YCSB
was only measuring times with millisecond granularity. This caused
transactions that took place in less than a second to be recorded
as taking 0 time to complete and as a result had the potential to
skew test results. This fix changes the timing granularity to
microseconds.

src/com/yahoo/ycsb/DBWrapper.java

@@ -83,10 +83,10 @@ public class DBWrapper extends DB
 	 */
 	public int read(String table, String key, Set<String> fields, HashMap<String,String> result)
 	{
-		long st=System.currentTimeMillis();
+		long st=System.nanoTime();
 		int res=_db.read(table,key,fields,result);
-		long en=System.currentTimeMillis();
-		_measurements.measure("READ",(int)(en-st));
+		long en=System.nanoTime();
+		_measurements.measure("READ",(int)((en-st)/1000));
 		_measurements.reportReturnCode("READ",res);
 		return res;
 	}
@@ -103,10 +103,10 @@ public class DBWrapper extends DB
 	 */
 	public int scan(String table, String startkey, int recordcount, Set<String> fields, Vector<HashMap<String,String>> result)
 	{
-		long st=System.currentTimeMillis();
+		long st=System.nanoTime();
 		int res=_db.scan(table,startkey,recordcount,fields,result);
-		long en=System.currentTimeMillis();
-		_measurements.measure("SCAN",(int)(en-st));
+		long en=System.nanoTime();
+		_measurements.measure("SCAN",(int)((en-st)/1000));
 		_measurements.reportReturnCode("SCAN",res);
 		return res;
 	}
@@ -122,10 +122,10 @@ public class DBWrapper extends DB
 	 */
 	public int update(String table, String key, HashMap<String,String> values)
 	{
-		long st=System.currentTimeMillis();
+		long st=System.nanoTime();
 		int res=_db.update(table,key,values);
-		long en=System.currentTimeMillis();
-		_measurements.measure("UPDATE",(int)(en-st));
+		long en=System.nanoTime();
+		_measurements.measure("UPDATE",(int)((en-st)/1000));
 		_measurements.reportReturnCode("UPDATE",res);
 		return res;
 	}
@@ -141,10 +141,10 @@ public class DBWrapper extends DB
 	 */
 	public int insert(String table, String key, HashMap<String,String> values)
 	{
-		long st=System.currentTimeMillis();
+		long st=System.nanoTime();
 		int res=_db.insert(table,key,values);
-		long en=System.currentTimeMillis();
-		_measurements.measure("INSERT",(int)(en-st));
+		long en=System.nanoTime();
+		_measurements.measure("INSERT",(int)((en-st)/1000));
 		_measurements.reportReturnCode("INSERT",res);
 		return res;
 	}
@@ -158,10 +158,10 @@ public class DBWrapper extends DB
 	 */
 	public int delete(String table, String key)
 	{
-		long st=System.currentTimeMillis();
+		long st=System.nanoTime();
 		int res=_db.delete(table,key);
-		long en=System.currentTimeMillis();
-		_measurements.measure("DELETE",(int)(en-st));
+		long en=System.nanoTime();
+		_measurements.measure("DELETE",(int)((en-st)/1000));
 		_measurements.reportReturnCode("DELETE",res);
 		return res;
 	}

src/com/yahoo/ycsb/measurements/OneMeasurementHistogram.java

@@ -86,13 +86,13 @@ public class OneMeasurementHistogram extends OneMeasurement
 	 */
 	public synchronized void measure(int latency)
 	{
-		if (latency>=_buckets)
+		if (latency/1000>=_buckets)
 		{
 			histogramoverflow++;
 		}
 		else
 		{
-			histogram[latency]++;
+			histogram[latency/1000]++;
 		}
 		operations++;
 		totallatency+=latency;
@@ -115,9 +115,9 @@ public class OneMeasurementHistogram extends OneMeasurement
   public void exportMeasurements(MeasurementsExporter exporter) throws IOException
   {
     exporter.write(getName(), "Operations", operations);
-    exporter.write(getName(), "AverageLatency(ms)", (((double)totallatency)/((double)operations)));
-    exporter.write(getName(), "MinLatency(ms)", min);
-    exporter.write(getName(), "MaxLatency(ms)", max);
+    exporter.write(getName(), "AverageLatency(us)", (((double)totallatency)/((double)operations)));
+    exporter.write(getName(), "MinLatency(us)", min);
+    exporter.write(getName(), "MaxLatency(us)", max);
     
     int opcounter=0;
     boolean done95th=false;
@@ -159,7 +159,7 @@ public class OneMeasurementHistogram extends OneMeasurement
 		double report=((double)windowtotallatency)/((double)windowoperations);
 		windowtotallatency=0;
 		windowoperations=0;
-		return "["+getName()+" AverageLatency(ms)="+d.format(report)+"]";
+		return "["+getName()+" AverageLatency(us)="+d.format(report)+"]";
 	}
 
 }

src/com/yahoo/ycsb/measurements/OneMeasurementTimeSeries.java

@@ -132,9 +132,9 @@ public class OneMeasurementTimeSeries extends OneMeasurement
     checkEndOfUnit(true);
 
     exporter.write(getName(), "Operations", operations);
-    exporter.write(getName(), "AverageLatency(ms)", (((double)totallatency)/((double)operations)));
-    exporter.write(getName(), "MinLatency(ms)", min);
-    exporter.write(getName(), "MaxLatency(ms)", max);
+    exporter.write(getName(), "AverageLatency(us)", (((double)totallatency)/((double)operations)));
+    exporter.write(getName(), "MinLatency(us)", min);
+    exporter.write(getName(), "MaxLatency(us)", max);
 
     //TODO: 95th and 99th percentile latency
 
@@ -173,7 +173,7 @@ public class OneMeasurementTimeSeries extends OneMeasurement
 		double report=((double)windowtotallatency)/((double)windowoperations);
 		windowtotallatency=0;
 		windowoperations=0;
-		return "["+getName()+" AverageLatency(ms)="+d.format(report)+"]";
+		return "["+getName()+" AverageLatency(us)="+d.format(report)+"]";
 	}
 
 }