From b1634591bc7103fa511c8a6a920b370641da3b0e Mon Sep 17 00:00:00 2001 From: Ben Pfaff Date: Fri, 20 Dec 2013 08:39:27 -0800 Subject: [PATCH] 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 Acked-by: Andy Zhou --- lib/ofp-print.c | 22 +++++++++++++++++++--- tests/ofp-print.at | 38 +++++++++++++++++++------------------- 2 files changed, 38 insertions(+), 22 deletions(-) diff --git a/lib/ofp-print.c b/lib/ofp-print.c index 0f7278cbb..4c89b3676 100644 --- 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 2f09c1b8b..989272c43 100644 --- 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 -- 2.20.1