| Message ID | 20170427010312.18249-2-joe@ovn.org |
|---|---|
| State | Accepted |
| Headers | show |
On Wed, Apr 26, 2017 at 06:03:12PM -0700, Joe Stringer wrote: > There are a few cases where more introspection into ukey transitions > would be relevant for logging or assertion. Track the SOURCE_LOCATOR and > thread id when states are transitioned and use these for logging. > > Suggested-by: Jarno Rajahalme <jarno@ovn.org> > Signed-off-by: Joe Stringer <joe@ovn.org> Very nice. Acked-by: Ben Pfaff <blp@ovn.org>
> On Apr 26, 2017, at 6:03 PM, Joe Stringer <joe@ovn.org> wrote: > > There are a few cases where more introspection into ukey transitions > would be relevant for logging or assertion. Track the SOURCE_LOCATOR and > thread id when states are transitioned and use these for logging. > > Suggested-by: Jarno Rajahalme <jarno@ovn.org> > Signed-off-by: Joe Stringer <joe@ovn.org> > --- > ofproto/ofproto-dpif-upcall.c | 17 ++++++++++++++++- > 1 file changed, 16 insertions(+), 1 deletion(-) > > diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c > index ccf15a3c80b3..8aff613161d9 100644 > --- a/ofproto/ofproto-dpif-upcall.c > +++ b/ofproto/ofproto-dpif-upcall.c > @@ -281,6 +281,10 @@ struct udpif_key { > uint64_t reval_seq OVS_GUARDED; /* Tracks udpif->reval_seq. */ > enum ukey_state state OVS_GUARDED; /* Tracks ukey lifetime. */ > > + /* 'state' debug information. */ > + unsigned int state_thread OVS_GUARDED; /* Thread that transitions. */ > + const char *state_where OVS_GUARDED; /* transition_ukey() locator. */ > + > /* Datapath flow actions as nlattrs. Protected by RCU. Read with > * ukey_get_actions(), and write with ukey_set_actions(). */ > OVSRCU_TYPE(struct ofpbuf *) actions; > @@ -1484,6 +1488,8 @@ ukey_create__(const struct nlattr *key, size_t key_len, > ukey->dump_seq = dump_seq; > ukey->reval_seq = reval_seq; > ukey->state = UKEY_CREATED; > + ukey->state_thread = ovsthread_id_self(); > + ukey->state_where = OVS_SOURCE_LOCATOR; > ukey->created = time_msec(); > memset(&ukey->stats, 0, sizeof ukey->stats); > ukey->stats.used = used; > @@ -1674,7 +1680,11 @@ static void > transition_ukey(struct udpif_key *ukey, enum ukey_state dst) > OVS_REQUIRES(ukey->mutex) > { > - ovs_assert(dst >= ukey->state); > + if (dst >= ukey->state) { > + VLOG_ABORT("Invalid ukey transition %d->%d (last transitioned from " > + "thread %u at %s)", ukey->state, dst, ukey->state_thread, > + ukey->state_where); > + } > if (ukey->state == dst && dst == UKEY_OPERATIONAL) { > return; > } > @@ -1709,6 +1719,8 @@ transition_ukey(struct udpif_key *ukey, enum ukey_state dst) > ds_cstr(&ds), ukey->state, dst); > ds_destroy(&ds); > } > + ukey->state_thread = ovsthread_id_self(); > + ukey->state_where = OVS_SOURCE_LOCATOR; You’ll want to evaluate OVS_SOURCE_LOCATOR at the caller of the transition_ukey() instead. Top do that you’ll need to add a “const char *where” argument, and then make a macro that uses OVS_SOURCE_LOCATOR as that additional argument, and make the callers use the new macro instead of calling the function directly. As is it will always report the same line (right here). Jarno > } > > static bool > @@ -2327,6 +2339,9 @@ revalidate(struct revalidator *revalidator) > /* The flow is now confirmed to be in the datapath. */ > transition_ukey(ukey, UKEY_OPERATIONAL); > } else { > + VLOG_INFO("Unexpected ukey transition from state %d " > + "(last transitioned from thread %u at %s)", > + ukey->state, ukey->state_thread, ukey->state_where); > ovs_mutex_unlock(&ukey->mutex); > continue; > } > -- > 2.11.1 >
diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c index ccf15a3c80b3..8aff613161d9 100644 --- a/ofproto/ofproto-dpif-upcall.c +++ b/ofproto/ofproto-dpif-upcall.c @@ -281,6 +281,10 @@ struct udpif_key { uint64_t reval_seq OVS_GUARDED; /* Tracks udpif->reval_seq. */ enum ukey_state state OVS_GUARDED; /* Tracks ukey lifetime. */ + /* 'state' debug information. */ + unsigned int state_thread OVS_GUARDED; /* Thread that transitions. */ + const char *state_where OVS_GUARDED; /* transition_ukey() locator. */ + /* Datapath flow actions as nlattrs. Protected by RCU. Read with * ukey_get_actions(), and write with ukey_set_actions(). */ OVSRCU_TYPE(struct ofpbuf *) actions; @@ -1484,6 +1488,8 @@ ukey_create__(const struct nlattr *key, size_t key_len, ukey->dump_seq = dump_seq; ukey->reval_seq = reval_seq; ukey->state = UKEY_CREATED; + ukey->state_thread = ovsthread_id_self(); + ukey->state_where = OVS_SOURCE_LOCATOR; ukey->created = time_msec(); memset(&ukey->stats, 0, sizeof ukey->stats); ukey->stats.used = used; @@ -1674,7 +1680,11 @@ static void transition_ukey(struct udpif_key *ukey, enum ukey_state dst) OVS_REQUIRES(ukey->mutex) { - ovs_assert(dst >= ukey->state); + if (dst >= ukey->state) { + VLOG_ABORT("Invalid ukey transition %d->%d (last transitioned from " + "thread %u at %s)", ukey->state, dst, ukey->state_thread, + ukey->state_where); + } if (ukey->state == dst && dst == UKEY_OPERATIONAL) { return; } @@ -1709,6 +1719,8 @@ transition_ukey(struct udpif_key *ukey, enum ukey_state dst) ds_cstr(&ds), ukey->state, dst); ds_destroy(&ds); } + ukey->state_thread = ovsthread_id_self(); + ukey->state_where = OVS_SOURCE_LOCATOR; } static bool @@ -2327,6 +2339,9 @@ revalidate(struct revalidator *revalidator) /* The flow is now confirmed to be in the datapath. */ transition_ukey(ukey, UKEY_OPERATIONAL); } else { + VLOG_INFO("Unexpected ukey transition from state %d " + "(last transitioned from thread %u at %s)", + ukey->state, ukey->state_thread, ukey->state_where); ovs_mutex_unlock(&ukey->mutex); continue; }
There are a few cases where more introspection into ukey transitions would be relevant for logging or assertion. Track the SOURCE_LOCATOR and thread id when states are transitioned and use these for logging. Suggested-by: Jarno Rajahalme <jarno@ovn.org> Signed-off-by: Joe Stringer <joe@ovn.org> --- ofproto/ofproto-dpif-upcall.c | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-)