forked from MirrorHub/synapse
Improve opentracing annotations for Notifier (#10111)
The existing tracing reports an error each time there is a timeout, which isn't really representative. Additionally, we log things about the way `wait_for_events` works (eg, the result of the callback) to the *parent* span, which is confusing.
This commit is contained in:
parent
73636cab69
commit
1d143074c5
2 changed files with 33 additions and 32 deletions
1
changelog.d/10111.misc
Normal file
1
changelog.d/10111.misc
Normal file
|
@ -0,0 +1 @@
|
||||||
|
Improve opentracing annotations for `Notifier`.
|
|
@ -485,21 +485,21 @@ class Notifier:
|
||||||
end_time = self.clock.time_msec() + timeout
|
end_time = self.clock.time_msec() + timeout
|
||||||
|
|
||||||
while not result:
|
while not result:
|
||||||
try:
|
with start_active_span("wait_for_events"):
|
||||||
now = self.clock.time_msec()
|
try:
|
||||||
if end_time <= now:
|
now = self.clock.time_msec()
|
||||||
break
|
if end_time <= now:
|
||||||
|
break
|
||||||
|
|
||||||
# Now we wait for the _NotifierUserStream to be told there
|
# Now we wait for the _NotifierUserStream to be told there
|
||||||
# is a new token.
|
# is a new token.
|
||||||
listener = user_stream.new_listener(prev_token)
|
listener = user_stream.new_listener(prev_token)
|
||||||
listener.deferred = timeout_deferred(
|
listener.deferred = timeout_deferred(
|
||||||
listener.deferred,
|
listener.deferred,
|
||||||
(end_time - now) / 1000.0,
|
(end_time - now) / 1000.0,
|
||||||
self.hs.get_reactor(),
|
self.hs.get_reactor(),
|
||||||
)
|
)
|
||||||
|
|
||||||
with start_active_span("wait_for_events.deferred"):
|
|
||||||
log_kv(
|
log_kv(
|
||||||
{
|
{
|
||||||
"wait_for_events": "sleep",
|
"wait_for_events": "sleep",
|
||||||
|
@ -517,27 +517,27 @@ class Notifier:
|
||||||
}
|
}
|
||||||
)
|
)
|
||||||
|
|
||||||
current_token = user_stream.current_token
|
current_token = user_stream.current_token
|
||||||
|
|
||||||
result = await callback(prev_token, current_token)
|
result = await callback(prev_token, current_token)
|
||||||
log_kv(
|
log_kv(
|
||||||
{
|
{
|
||||||
"wait_for_events": "result",
|
"wait_for_events": "result",
|
||||||
"result": bool(result),
|
"result": bool(result),
|
||||||
}
|
}
|
||||||
)
|
)
|
||||||
if result:
|
if result:
|
||||||
|
break
|
||||||
|
|
||||||
|
# Update the prev_token to the current_token since nothing
|
||||||
|
# has happened between the old prev_token and the current_token
|
||||||
|
prev_token = current_token
|
||||||
|
except defer.TimeoutError:
|
||||||
|
log_kv({"wait_for_events": "timeout"})
|
||||||
|
break
|
||||||
|
except defer.CancelledError:
|
||||||
|
log_kv({"wait_for_events": "cancelled"})
|
||||||
break
|
break
|
||||||
|
|
||||||
# Update the prev_token to the current_token since nothing
|
|
||||||
# has happened between the old prev_token and the current_token
|
|
||||||
prev_token = current_token
|
|
||||||
except defer.TimeoutError:
|
|
||||||
log_kv({"wait_for_events": "timeout"})
|
|
||||||
break
|
|
||||||
except defer.CancelledError:
|
|
||||||
log_kv({"wait_for_events": "cancelled"})
|
|
||||||
break
|
|
||||||
|
|
||||||
if result is None:
|
if result is None:
|
||||||
# This happened if there was no timeout or if the timeout had
|
# This happened if there was no timeout or if the timeout had
|
||||||
|
|
Loading…
Reference in a new issue