ofp-print: Print durations with at least three decimals.

Occasionally I run a command like this:
    watch -n.1 ovs-ofctl dump-flows br0
to see how flows change over time.  Until now, it has been more difficult
than necessary to spot real changes, because flows "jump around" as the
number of decimals printed for duration changes from moment to moment.
That is, you might see
    cookie=0x0, duration=4.566s, table=0, n_packets=0, ...
one moment, and then
    cookie=0x0, duration=4.8s, table=0, n_packets=0, ...
the next moment.  Shortening 4.8 to 4.800 shifts everything following it
two places to the left, creating a visual jump.

This commit avoids that problem by always printing at least three decimals
if we print any.  There can still be an occasional jump if a duration is
exactly on a second boundary, but that only happens 1/1000 of the time.

Signed-off-by: Ben Pfaff <blp@nicira.com>
Acked-by: Andy Zhou <azhou@nicira.com>

diff --git a/lib/ofp-print.c b/lib/ofp-print.c
index 0f7278c..4c89b36 100644 (file)
--- a/lib/ofp-print.c
+++ b/lib/ofp-print.c
@@ -860,10 +860,26 @@ static void
 ofp_print_duration(struct ds *string, unsigned int sec, unsigned int nsec)
 {
     ds_put_format(string, "%u", sec);
+
+    /* If there are no fractional seconds, don't print any decimals.
+     *
+     * If the fractional seconds can be expressed exactly as milliseconds,
+     * print 3 decimals.  Open vSwitch provides millisecond precision for most
+     * time measurements, so printing 3 decimals every time makes it easier to
+     * spot real changes in flow dumps that refresh themselves quickly.
+     *
+     * If the fractional seconds are more precise than milliseconds, print the
+     * number of decimals needed to express them exactly.
+     */
     if (nsec > 0) {
-        ds_put_format(string, ".%09u", nsec);
-        while (string->string[string->length - 1] == '0') {
-            string->length--;
+        unsigned int msec = nsec / 1000000;
+        if (msec * 1000000 == nsec) {
+            ds_put_format(string, ".%03u", msec);
+        } else {
+            ds_put_format(string, ".%09u", nsec);
+            while (string->string[string->length - 1] == '0') {
+                string->length--;
+            }
         }
     }
     ds_put_char(string, 's');

diff --git a/tests/ofp-print.at b/tests/ofp-print.at
index 2f09c1b..989272c 100644 (file)
--- a/tests/ofp-print.at
+++ b/tests/ofp-print.at
@@ -558,7 +558,7 @@ AT_CHECK([ovs-ofctl ofp-print "\
 30 e0 35 00 00 05 00 00 00 00 00 00 00 00 00 01 \
 00 00 00 00 00 00 00 3c \
 "], [0], [dnl
-OFPT_FLOW_REMOVED (xid=0x0): priority=65535,arp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,arp_spa=192.168.0.1,arp_tpa=192.168.0.2,arp_op=2,nw_tos=0,tp_src=0,tp_dst=0 reason=idle duration5.82s idle5 pkts1 bytes60
+OFPT_FLOW_REMOVED (xid=0x0): priority=65535,arp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,arp_spa=192.168.0.1,arp_tpa=192.168.0.2,arp_op=2,nw_tos=0,tp_src=0,tp_dst=0 reason=idle duration5.820s idle5 pkts1 bytes60
 ])
 AT_CLEANUP
 
@@ -569,7 +569,7 @@ AT_CHECK([ovs-ofctl ofp-print "\
 80 00 01 05 00 00 00 01 00 98 96 80 00 3c 00 78 \
 00 00 00 00 00 12 d6 87 00 00 00 00 6f 68 ba 66 \
 00 01 00 0a 80 00 0c 02 10 09 00 00 00 00 00 00"], [0], [dnl
-OFPT_FLOW_REMOVED (OF1.2) (xid=0x0): dl_vlan=9 reason=hard table_id=5 cookie:0xfedcba9876543210 duration1.01s idle60 hard120 pkts1234567 bytes1869134438
+OFPT_FLOW_REMOVED (OF1.2) (xid=0x0): dl_vlan=9 reason=hard table_id=5 cookie:0xfedcba9876543210 duration1.010s idle60 hard120 pkts1234567 bytes1869134438
 ])
 AT_CLEANUP
 
@@ -580,7 +580,7 @@ AT_CHECK([ovs-ofctl ofp-print "\
 80 00 01 05 00 00 00 01 00 98 96 80 00 3c 00 78 \
 00 00 00 00 00 12 d6 87 00 00 00 00 6f 68 ba 66 \
 00 01 00 0a 80 00 0c 02 10 09 00 00 00 00 00 00"], [0], [dnl
-OFPT_FLOW_REMOVED (OF1.3) (xid=0x0): dl_vlan=9 reason=hard table_id=5 cookie:0xfedcba9876543210 duration1.01s idle60 hard120 pkts1234567 bytes1869134438
+OFPT_FLOW_REMOVED (OF1.3) (xid=0x0): dl_vlan=9 reason=hard table_id=5 cookie:0xfedcba9876543210 duration1.010s idle60 hard120 pkts1234567 bytes1869134438
 ])
 AT_CLEANUP
 
@@ -1192,9 +1192,9 @@ c0 a8 00 02 00 08 00 00 00 00 00 09 05 b8 d8 00 \
 00 00 00 00 00 00 00 00 \
 "], [0], [dnl
 OFPST_FLOW reply (xid=0x4):
- cookie=0x0, duration=4.2s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,arp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,arp_spa=192.168.0.1,arp_tpa=192.168.0.2,arp_op=2,nw_tos=0,tp_src=0,tp_dst=0 actions=output:1
- cookie=0x0, duration=8.9s, table=0, n_packets=13, n_bytes=1274, idle_timeout=5, priority=65535,icmp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,icmp_type=0,icmp_code=0 actions=output:3
- cookie=0x0, duration=4.28s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,arp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,arp_spa=192.168.0.2,arp_tpa=192.168.0.1,arp_op=1,nw_tos=0,tp_src=0,tp_dst=0 actions=output:3
+ cookie=0x0, duration=4.200s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,arp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,arp_spa=192.168.0.1,arp_tpa=192.168.0.2,arp_op=2,nw_tos=0,tp_src=0,tp_dst=0 actions=output:1
+ cookie=0x0, duration=8.900s, table=0, n_packets=13, n_bytes=1274, idle_timeout=5, priority=65535,icmp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,icmp_type=0,icmp_code=0 actions=output:3
+ cookie=0x0, duration=4.280s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,arp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,arp_spa=192.168.0.2,arp_tpa=192.168.0.1,arp_op=1,nw_tos=0,tp_src=0,tp_dst=0 actions=output:3
  cookie=0x0, duration=9.096s, table=0, n_packets=13, n_bytes=1274, idle_timeout=5, icmp,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,icmp_type=8,icmp_code=0 actions=output:1
  cookie=0x0, duration=0s, table=2, n_packets=0, n_bytes=0, actions=drop
 ])
@@ -1718,11 +1718,11 @@ AT_CHECK([ovs-ofctl ofp-print "\
 ff ff ff ff ff ff ff ff \
 "], [0], [dnl
 OFPST_QUEUE reply (OF1.3) (xid=0x1): 6 queues
-  port 3 queue 1: bytes=302, pkts=1, errors=0, duration=100.5s
-  port 3 queue 2: bytes=0, pkts=0, errors=0, duration=100.5s
-  port 2 queue 1: bytes=2100, pkts=20, errors=0, duration=100.5s
-  port 2 queue 2: bytes=0, pkts=0, errors=0, duration=100.5s
-  port 1 queue 1: bytes=0, pkts=0, errors=0, duration=100.5s
+  port 3 queue 1: bytes=302, pkts=1, errors=0, duration=100.500s
+  port 3 queue 2: bytes=0, pkts=0, errors=0, duration=100.500s
+  port 2 queue 1: bytes=2100, pkts=20, errors=0, duration=100.500s
+  port 2 queue 2: bytes=0, pkts=0, errors=0, duration=100.500s
+  port 1 queue 1: bytes=0, pkts=0, errors=0, duration=100.500s
   port 1 queue 2: bytes=0, pkts=0, errors=0, duration=?
 ])
 AT_CLEANUP
@@ -1773,8 +1773,8 @@ AT_CHECK([ovs-ofctl ofp-print "\
 00 00 00 00 00 00 11 11 00 00 00 00 00 22 22 22 \
 "], [0], [dnl
 OFPST_GROUP reply (OF1.3) (xid=0x2):
- group_id=2271560481,duration=18.5s,ref_count=4,packet_count=34952,byte_count=7829367,bucket0:packet_count=4369,byte_count=2236962,bucket1:packet_count=4369,byte_count=2236962,bucket2:packet_count=26214,byte_count=3355443
- group_id=5,duration=16.5s,ref_count=2,packet_count=34952,byte_count=7829367,bucket0:packet_count=4369,byte_count=2236962,bucket1:packet_count=4369,byte_count=2236962
+ group_id=2271560481,duration=18.500s,ref_count=4,packet_count=34952,byte_count=7829367,bucket0:packet_count=4369,byte_count=2236962,bucket1:packet_count=4369,byte_count=2236962,bucket2:packet_count=26214,byte_count=3355443
+ group_id=5,duration=16.500s,ref_count=2,packet_count=34952,byte_count=7829367,bucket0:packet_count=4369,byte_count=2236962,bucket1:packet_count=4369,byte_count=2236962
 ])
 AT_CLEANUP
 
@@ -2521,20 +2521,20 @@ ff ff 00 18 00 00 23 20 00 07 00 1f 00 01 00 04 \
 "], [0],
 [[NXST_FLOW reply (xid=0x4):
  cookie=0x0, duration=1.048s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2535,tp_dst=0 actions=output:1
- cookie=0x0, duration=3.84s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, idle_age=2, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2532,tp_dst=0 actions=output:1
+ cookie=0x0, duration=3.840s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, idle_age=2, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2532,tp_dst=0 actions=output:1
  cookie=0x0, duration=2.872s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, idle_age=4, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2533 actions=output:3
  cookie=0x0, duration=4.756s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, idle_age=0, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2531,tp_dst=0 actions=output:1
- cookie=0x0, duration=2.88s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, hard_timeout=10, idle_age=2, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2533,tp_dst=0 actions=output:1
+ cookie=0x0, duration=2.880s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, hard_timeout=10, idle_age=2, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2533,tp_dst=0 actions=output:1
  cookie=0x0, duration=5.672s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2530,tp_dst=0 actions=output:1
- cookie=0x0, duration=1.04s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2535 actions=output:3
+ cookie=0x0, duration=1.040s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2535 actions=output:3
  cookie=0x0, duration=1.952s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2534 actions=output:3
  cookie=0x0, duration=4.668s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2531 actions=output:3
  cookie=0x0, duration=3.752s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2532 actions=output:3
  cookie=0x0, duration=0.172s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2536,tp_dst=0 actions=output:1
  cookie=0x0, duration=5.624s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2530 actions=output:3
- cookie=0x0, duration=0.08s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2536 actions=output:3
- cookie=0x0, duration=1.96s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2534,tp_dst=0 actions=output:1
- cookie=0x0, duration=228.78s, table=0, n_packets=0, n_bytes=0, reg0=0x7b,tun_id=0x1c8 actions=load:0x5->NXM_NX_REG0[]
+ cookie=0x0, duration=0.080s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:06,dl_dst=50:54:00:00:00:05,nw_src=192.168.0.2,nw_dst=192.168.0.1,nw_tos=0,tp_src=0,tp_dst=2536 actions=output:3
+ cookie=0x0, duration=1.960s, table=0, n_packets=1, n_bytes=60, idle_timeout=5, priority=65535,tcp,in_port=3,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:06,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,tp_src=2534,tp_dst=0 actions=output:1
+ cookie=0x0, duration=228.780s, table=0, n_packets=0, n_bytes=0, reg0=0x7b,tun_id=0x1c8 actions=load:0x5->NXM_NX_REG0[]
  cookie=0x0, duration=3600.0005s, table=1, n_packets=100, n_bytes=6400, actions=drop
 ]])
 AT_CLEANUP