On Thu, Dec 19, 2013 at 03:53:17PM -0800, Andy Zhou wrote:
> On Thu, Dec 19, 2013 at 10:11 AM, Ben Pfaff <b...@nicira.com> wrote:
>
> > 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 <b...@nicira.com>
> > ---
> > lib/ofp-print.c | 22 +++++++++++++++++++---
> > 1 file changed, 19 insertions(+), 3 deletions(-)
> >
> > diff --git a/lib/ofp-print.c b/lib/ofp-print.c
> > index 0f7278c..286af6f 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 factional seconds are more precise than milliseconds, print
> > the
> >
> s/factional/fractional
>
> > + * 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');
> >
>
> Acked-by: Andy Zhou <az...@nicira.com>
Thanks. I fixed the comment typo that you pointed out.
When I ran the tests, I discovered that I had to fix up a number of them
that were sensitive to the change in format. Here's what I'm pushing:
--8<--------------------------cut here-------------------------->8--
From: Ben Pfaff <b...@nicira.com>
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 <b...@nicira.com>
Acked-by: Andy Zhou <az...@nicira.com>
---
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 0f7278c..4c89b36 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 2f09c1b..989272c 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
--
1.7.10.4
_______________________________________________
dev mailing list
dev@openvswitch.org
http://openvswitch.org/mailman/listinfo/dev
