@@ -253,10 +253,14 @@ def decrypt_token(self, username, token):
253253 version < self .minimum_token_version ):
254254 raise TokenValidationError ('Unacceptable token version.' )
255255 if self .stats :
256+ parse_duration = (datetime .datetime .utcnow () - time_start ).total_seconds () * 1000 # noqa: E501
257+ self .stats .timing ('username_parse_duration' , parse_duration ) # noqa: E501
256258 self .stats .incr ('token_version_{version}' )
257259 self .stats .incr (f'cache_key_from_{ _from } ' )
258260 self .stats .incr (f'cache_key_to_{ self .to_auth_context } ' )
259261 self .stats .incr (f'cache_key_user_type_{ user_type } ' )
262+
263+ cache_key_gen_start = datetime .datetime .utcnow ()
260264 try :
261265 token_key = '{0}{1}{2}{3}' .format (
262266 hashlib .sha256 (ensure_bytes (token )).hexdigest (),
@@ -266,7 +270,17 @@ def decrypt_token(self, username, token):
266270 )
267271 except Exception :
268272 raise TokenValidationError ('Authentication error.' )
269- if token_key not in self .TOKENS :
273+ if self .stats :
274+ cache_key_duration = (datetime .datetime .utcnow () - cache_key_gen_start ).total_seconds () * 1000 # noqa: E501
275+ self .stats .timing ('cache_key_generation_duration' , cache_key_duration ) # noqa: E501
276+
277+ cache_lookup_start = datetime .datetime .utcnow ()
278+ cache_miss = token_key not in self .TOKENS
279+ if self .stats :
280+ cache_lookup_duration = (datetime .datetime .utcnow () - cache_lookup_start ).total_seconds () * 1000 # noqa: E501
281+ self .stats .timing ('cache_lookup_duration' , cache_lookup_duration ) # noqa: E501
282+
283+ if cache_miss :
270284 if self .stats :
271285 self .stats .incr ('token_cache_miss' )
272286 self .stats .gauge ('token_cache_size_at_miss' , len (self .TOKENS ))
@@ -338,12 +352,20 @@ def decrypt_token(self, username, token):
338352 'Authentication error. General error.'
339353 )
340354 else :
355+ cache_hit_start = datetime .datetime .utcnow ()
341356 if self .stats :
342357 self .stats .incr ('token_cache_hit' )
343358 ret = self .TOKENS [token_key ]
359+ if self .stats :
360+ cache_hit_duration = (datetime .datetime .utcnow () - cache_hit_start ).total_seconds () * 1000 # noqa: E501
361+ self .stats .timing ('cache_hit_lookup_duration' , cache_hit_duration ) # noqa: E501
344362
345363 now = datetime .datetime .utcnow ()
346364 if self .stats :
365+ # Total time from start to this point (before time validation)
366+ pre_time_validation_duration = (now - time_start ).total_seconds () * 1000 # noqa: E501
367+ self .stats .timing ('pre_time_validation_duration' , pre_time_validation_duration ) # noqa: E501
368+ # Original total validation duration metric
347369 self .stats .timing ('decrypt_token_validation_duration' , (now - time_start ).total_seconds () * 1000 ) # noqa: E501
348370 time_validation_start = datetime .datetime .utcnow ()
349371 try :
@@ -377,7 +399,12 @@ def decrypt_token(self, username, token):
377399 time_validation_duration = (datetime .datetime .utcnow () - time_validation_start ).total_seconds () * 1000 # noqa: E501
378400 self .stats .timing ('time_validation_duration' , time_validation_duration ) # noqa: E501
379401
402+ cache_set_start = datetime .datetime .utcnow ()
380403 self .TOKENS [token_key ] = ret
404+ if self .stats :
405+ cache_set_duration = (datetime .datetime .utcnow () - cache_set_start ).total_seconds () * 1000 # noqa: E501
406+ self .stats .timing ('cache_set_duration' , cache_set_duration ) # noqa: E501
407+
381408 duration = (datetime .datetime .utcnow () - now ).total_seconds () * 1000 # noqa: E501
382409 if self .stats :
383410 self .stats .timing ('decrypt_token_duration_post_validation' , duration ) # noqa: E501
0 commit comments