)]}'
{"/PATCHSET_LEVEL":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5a4cb22b4fcae0a91557e1ba77f8ec1900903cbc","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":5,"id":"c7cb0999_6f154ee5","updated":"2025-07-03 01:51:05.000000000","message":"The timing_breakdown can only be None or dict. did we want to add the dict check? And if so test. For belts and braces.","commit_id":"80f8b5418bbdda3cd00d0c7161edeb02581d0e28"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":6,"id":"34ad51c1_3538630a","updated":"2025-07-04 17:48:33.000000000","message":"I looked ahead to one of the following patches to get a sense of how this will be used.\n\n*I may be missing some context* but it seems like there is some overly defensive code in the helpers that is actually covering what I would consider bugs. See inline comments.\n\nI think the interface could, and should, be simpler so that the changes to decorated methods are minimised. In particular, the decorate method shouldn\u0027t be exposed to updating start times etc - that feels like the implementation requirements of the decorator bleeding out (i.e. that it wants to record time *deltas*).\n\nI could imagine something like this, but *I have not run the following code!*:\n\n```\nclass TimingBreakdown:\n    def __init__(self):\n        self.start \u003d time.time()\n        self.timings \u003d []\n    \n    def record(self, event):\n        self.timings.append((event, time.time() - self.start))\n        \n    def update(self, event):\n        # if there is a use case for cumulative timing\n        # then look for the last entry for event in self.events and increment\n        # its delta\n\ndef decorated_function(timing_breakdown):\n    # my business is moving bytes to/from disk;\n    # I don\u0027t want to start tracking time, but I don\u0027t mind doing\n    # the minimum to let someone else know how things are progressing\n    # and they can track timings if they want to.\n\n    # do stuff\n    timing_breakdown.record(\u0027stuff done\u0027)\n    # do more stuff\n    timing_breakdown.record(\u0027more stuff done\u0027) \n    # do stuff again\n    timing_breakdown.record(\u0027stuff done\u0027)\n\n```","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"d4b77ebfaba6667bf8b038d9788c9f672963ac5b","unresolved":true,"context_lines":[],"source_content_type":"","patch_set":6,"id":"96951e34_be4d462f","in_reply_to":"34ad51c1_3538630a","updated":"2025-07-08 03:18:34.000000000","message":"In the typical usages, ``record_slow_timing`` takes the ``timing_start`` parameter and assign the returned value (last ``time.time()`` within the function call) to ``timing_start``, this is used to save one extra ``time.time()`` call.\nhttps://review.opendev.org/c/openstack/swift/+/951219/7/swift/obj/server.py#1291\n\n```\ntiming_start \u003d record_slow_timing(\n            timing_breakdown, \u0027diskfile_acquisition\u0027, timing_start)\n```","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"ccc060d3daab125d83d66fe243907dbd527d9879","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":6,"id":"f6d0805b_eb77decf","in_reply_to":"96951e34_be4d462f","updated":"2025-08-22 05:21:51.000000000","message":"Done","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"2a7dcbf23bccf000f1f7bbd38edc0ed1435e14f7","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":8,"id":"e642800e_f3752e47","updated":"2025-08-21 17:20:36.000000000","message":"As a generic tool I think it would be good to clarify the expectations around repeated events: is the caller expected to *not* repeat the same event name (in which case, should an exception be raised) or are repeated events expected, in which case is is helpful to have them replace the previous timing value bit appear to have occurred at the previous position in the order?\n\nI think I\u0027d prefer repeated events to be allowed but create individual records in the breakdown.","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":8,"id":"3cf0d435_6bc5da36","updated":"2025-08-20 05:30:48.000000000","message":"thanks for the reviews!","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"ccc060d3daab125d83d66fe243907dbd527d9879","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":8,"id":"183d3caf_28090083","in_reply_to":"e642800e_f3752e47","updated":"2025-08-22 05:21:51.000000000","message":"In my previous patch, I wanted to only implement what we need so far and don\u0027t support if caller record the same event name repeatedly, since I feel caller is expected to divide the time of the whole function into timings of unique sub steps. Even there are multiple sub steps are doing the same thing, caller can give them unique names, like SAME_TASK_1, SAME_TASK_2 and etc.\n\nHowever, I agree with you, maybe some cases would like to use repeated names, it doesn\u0027t hurt for this new decorator to support it.","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"df931274_53b921b6","updated":"2025-08-22 09:50:54.000000000","message":"LGTM. Holding off merging until we are happy with one of the use cases in following patches.\n\nMy \u0027nit\u0027 comments are based on years of learning from others, and debugging test failures... when a test fails we want to have the most information available in the failure report about the failure cause. But they are not blockers.","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"9e5cd56f7a059330103d9ed475cf4501068f398b","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":11,"id":"385e2ed7_02b189fd","updated":"2026-02-13 23:43:28.000000000","message":"recheck","commit_id":"4c3e95ef100f8b7c2f3c60beb7ab78c2c25972be"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"49d3063d71a2d75667c60d4d56bb8e00efe3b92b","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":12,"id":"67f13880_33fbfd8d","updated":"2026-03-10 20:01:53.000000000","message":"I don\u0027t care much for this interface and hope/expect that we throw it out and replace it with otel rather that make deeper investment into a home-rolled less featureful implementation of a standard pattern for capturing and visualizing and debugging problems using tracing instrumentation.\n\nI don\u0027t think we\u0027re going to do something in-tree that\u0027s better than `opentelemetry-sdk` - and if we try we\u0027re going to waste time re-learning why they have made the tradeoffs they did.","commit_id":"9a1adb5c67fa0022ed4880c0202aca5f3d0e2b21"}],"swift/common/base_storage_server.py":[{"author":{"_account_id":36606,"name":"Yan Xiao","display_name":"Yan","email":"yanxiao@nvidia.com","username":"yanxiao"},"change_message_id":"92462e16ba606cb4de5c718d0c88bee7612e3c81","unresolved":true,"context_lines":[{"line_number":30,"context_line":"def slow_request_logging(threshold_attr\u003dNone):"},{"line_number":31,"context_line":"    \"\"\""},{"line_number":32,"context_line":"    Returns a decorator that logs slow operations with timing breakdown. The"},{"line_number":33,"context_line":"    function must accept the \u0027timing_breakdown\u0027 parameter."},{"line_number":34,"context_line":""},{"line_number":35,"context_line":"    :param threshold_attr: The attribute name of the controller class that"},{"line_number":36,"context_line":"        contains the slow threshold for the operation; if not provided,"}],"source_content_type":"text/x-python","patch_set":4,"id":"a921d7ce_8899788b","line":33,"updated":"2025-06-16 15:29:55.000000000","message":"should we specify that as kwarg parameter?","commit_id":"155bc4c58848538ec6c4458204f915e072ce2f67"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"e2a8a86c87b00a26cd07c5ea4d739c0f98466394","unresolved":false,"context_lines":[{"line_number":30,"context_line":"def slow_request_logging(threshold_attr\u003dNone):"},{"line_number":31,"context_line":"    \"\"\""},{"line_number":32,"context_line":"    Returns a decorator that logs slow operations with timing breakdown. The"},{"line_number":33,"context_line":"    function must accept the \u0027timing_breakdown\u0027 parameter."},{"line_number":34,"context_line":""},{"line_number":35,"context_line":"    :param threshold_attr: The attribute name of the controller class that"},{"line_number":36,"context_line":"        contains the slow threshold for the operation; if not provided,"}],"source_content_type":"text/x-python","patch_set":4,"id":"4c6513d1_1f10c90a","line":33,"in_reply_to":"a921d7ce_8899788b","updated":"2025-07-02 21:06:12.000000000","message":"Done","commit_id":"155bc4c58848538ec6c4458204f915e072ce2f67"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5a4cb22b4fcae0a91557e1ba77f8ec1900903cbc","unresolved":true,"context_lines":[{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."},{"line_number":83,"context_line":"    \"\"\""},{"line_number":84,"context_line":"    if timing_breakdown is not None:"},{"line_number":85,"context_line":"        now \u003d time.time()"},{"line_number":86,"context_line":"        # Add the duration to the existing value for this key"},{"line_number":87,"context_line":"        timing_breakdown[key] +\u003d now - timing_start"}],"source_content_type":"text/x-python","patch_set":5,"id":"680af08b_50d2cc01","line":84,"updated":"2025-07-03 01:51:05.000000000","message":"```\nand isinstance(timing_breakdown, dict):\n```\n\nMaybe?","commit_id":"80f8b5418bbdda3cd00d0c7161edeb02581d0e28"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"bc6f1da524dbf948e05a8bf2a366437587b74610","unresolved":false,"context_lines":[{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."},{"line_number":83,"context_line":"    \"\"\""},{"line_number":84,"context_line":"    if timing_breakdown is not None:"},{"line_number":85,"context_line":"        now \u003d time.time()"},{"line_number":86,"context_line":"        # Add the duration to the existing value for this key"},{"line_number":87,"context_line":"        timing_breakdown[key] +\u003d now - timing_start"}],"source_content_type":"text/x-python","patch_set":5,"id":"ff33e167_f1edccff","line":84,"in_reply_to":"680af08b_50d2cc01","updated":"2025-07-03 19:20:42.000000000","message":"Done","commit_id":"80f8b5418bbdda3cd00d0c7161edeb02581d0e28"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":28,"context_line":"DEFAULT_SLOW_REQUEST_THRESHOLD \u003d 60.0"},{"line_number":29,"context_line":""},{"line_number":30,"context_line":""},{"line_number":31,"context_line":"def slow_request_logging(threshold_attr\u003dNone):"},{"line_number":32,"context_line":"    \"\"\""},{"line_number":33,"context_line":"    Returns a decorator that logs slow operations with timing breakdown. The"},{"line_number":34,"context_line":"    function must accept the \u0027timing_breakdown\u0027 parameter."}],"source_content_type":"text/x-python","patch_set":6,"id":"3a95ba8a_c333f487","line":31,"range":{"start_line":31,"start_character":4,"end_line":31,"end_character":9},"updated":"2025-07-04 17:48:33.000000000","message":"nit: I totally understand the context for this is debugging slow requests, but *in general* the decorator is agnostic as to whether a request is subjectively slow or not. threshold_attr could be set to zero if someone wanted to trace all requests. In fact, it is the value of threshold_attr, not the application of the decorator, that determines if we\u0027re logging \u0027slow requests\u0027 or \u0027quite fast requests\u0027 or whatever.\n\nSo I\u0027d suggest a rename to something like ``request_timing_logging``","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":28,"context_line":"DEFAULT_SLOW_REQUEST_THRESHOLD \u003d 60.0"},{"line_number":29,"context_line":""},{"line_number":30,"context_line":""},{"line_number":31,"context_line":"def slow_request_logging(threshold_attr\u003dNone):"},{"line_number":32,"context_line":"    \"\"\""},{"line_number":33,"context_line":"    Returns a decorator that logs slow operations with timing breakdown. The"},{"line_number":34,"context_line":"    function must accept the \u0027timing_breakdown\u0027 parameter."}],"source_content_type":"text/x-python","patch_set":6,"id":"51ebc225_c03b2060","line":31,"range":{"start_line":31,"start_character":4,"end_line":31,"end_character":9},"in_reply_to":"3a95ba8a_c333f487","updated":"2025-08-20 05:30:48.000000000","message":"Done","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":35,"context_line":""},{"line_number":36,"context_line":"    :param threshold_attr: The attribute name of the controller class that"},{"line_number":37,"context_line":"        contains the slow threshold for the operation; if not provided,"},{"line_number":38,"context_line":"        the default threshold DEFAULT_SLOW_REQUEST_THRESHOLD is used."},{"line_number":39,"context_line":"    \"\"\""},{"line_number":40,"context_line":"    def decorating_func(func):"},{"line_number":41,"context_line":"        @functools.wraps(func)"}],"source_content_type":"text/x-python","patch_set":6,"id":"39ae0a9a_6a6b1688","line":38,"updated":"2025-07-04 17:48:33.000000000","message":"what\u0027s the use case for a dev using the decorator but not having an threshold attr available?\n\nI can imagine a dev wanting to apply the decorator but not having time/inclination to add an appropriate *configurable* attr. But in that case, the dev could at least add a hard-coded attr to to the same class that is being decorated.\n\nSo the DEFAULT_SLOW_REQUEST_THRESHOLD seems unnecessary, and brittle (you either add an attr or you get 60 seconds).","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":35,"context_line":""},{"line_number":36,"context_line":"    :param threshold_attr: The attribute name of the controller class that"},{"line_number":37,"context_line":"        contains the slow threshold for the operation; if not provided,"},{"line_number":38,"context_line":"        the default threshold DEFAULT_SLOW_REQUEST_THRESHOLD is used."},{"line_number":39,"context_line":"    \"\"\""},{"line_number":40,"context_line":"    def decorating_func(func):"},{"line_number":41,"context_line":"        @functools.wraps(func)"}],"source_content_type":"text/x-python","patch_set":6,"id":"ebaa9d8d_8931ab07","line":38,"in_reply_to":"39ae0a9a_6a6b1688","updated":"2025-08-20 05:30:48.000000000","message":"Good point! ``DEFAULT_SLOW_REQUEST_THRESHOLD`` is not necessary, I will get it removed.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":55,"context_line":"            threshold \u003d (getattr(ctrl, threshold_attr,"},{"line_number":56,"context_line":"                                 DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":57,"context_line":"                         if threshold_attr"},{"line_number":58,"context_line":"                         else DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":59,"context_line":"            if total_time \u003e threshold:"},{"line_number":60,"context_line":"                timing_parts \u003d []"},{"line_number":61,"context_line":"                for operation, duration in timing_breakdown.items():"}],"source_content_type":"text/x-python","patch_set":6,"id":"a086e850_f5d51f86","line":58,"updated":"2025-07-04 17:48:33.000000000","message":"nit: if you made the default ``threshold_attr`` arg be ``\u0027\u0027`` then this can be simplified to \n\n```\nthreshold \u003d getattr(ctrl, threshold_attr,\n                                 DEFAULT_SLOW_REQUEST_THRESHOLD)\n                                 ```\n\ni.e. no need for the if/else\n\nbut (see comment above) I\u0027m inclined to think that if threshold_attr does not exist then that\u0027s a coding error","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":55,"context_line":"            threshold \u003d (getattr(ctrl, threshold_attr,"},{"line_number":56,"context_line":"                                 DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":57,"context_line":"                         if threshold_attr"},{"line_number":58,"context_line":"                         else DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":59,"context_line":"            if total_time \u003e threshold:"},{"line_number":60,"context_line":"                timing_parts \u003d []"},{"line_number":61,"context_line":"                for operation, duration in timing_breakdown.items():"}],"source_content_type":"text/x-python","patch_set":6,"id":"92660d2d_6645c25f","line":58,"in_reply_to":"a086e850_f5d51f86","updated":"2025-08-20 05:30:48.000000000","message":"Done","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":56,"context_line":"                                 DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":57,"context_line":"                         if threshold_attr"},{"line_number":58,"context_line":"                         else DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":59,"context_line":"            if total_time \u003e threshold:"},{"line_number":60,"context_line":"                timing_parts \u003d []"},{"line_number":61,"context_line":"                for operation, duration in timing_breakdown.items():"},{"line_number":62,"context_line":"                    timing_parts.append("}],"source_content_type":"text/x-python","patch_set":6,"id":"b5c29887_25f2d9e0","line":59,"range":{"start_line":59,"start_character":28,"end_line":59,"end_character":37},"updated":"2025-07-04 17:48:33.000000000","message":"ok, so if threshold is not a number then that implies the dev has written a bug: either ``threshold_attr`` is wrong or the value of ``threshold_attr`` has not been correctly validated when the controller was init\u0027d.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":56,"context_line":"                                 DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":57,"context_line":"                         if threshold_attr"},{"line_number":58,"context_line":"                         else DEFAULT_SLOW_REQUEST_THRESHOLD)"},{"line_number":59,"context_line":"            if total_time \u003e threshold:"},{"line_number":60,"context_line":"                timing_parts \u003d []"},{"line_number":61,"context_line":"                for operation, duration in timing_breakdown.items():"},{"line_number":62,"context_line":"                    timing_parts.append("}],"source_content_type":"text/x-python","patch_set":6,"id":"b917e2bf_d039fb1a","line":59,"range":{"start_line":59,"start_character":28,"end_line":59,"end_character":37},"in_reply_to":"b5c29887_25f2d9e0","updated":"2025-08-20 05:30:48.000000000","message":"Acknowledged","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":63,"context_line":"                        \u0027%s\u003d%.3fs\u0027 % (operation, duration))"},{"line_number":64,"context_line":"                ctrl.logger.warning("},{"line_number":65,"context_line":"                    \u0027Slow %s (%.3fs) for %s, status %d, %s\u0027,"},{"line_number":66,"context_line":"                    req.method, total_time, req.path, resp.status_int,"},{"line_number":67,"context_line":"                    \u0027, \u0027.join(timing_parts)"},{"line_number":68,"context_line":"                )"},{"line_number":69,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"60453237_e67e6022","line":66,"updated":"2025-07-04 17:48:33.000000000","message":"it\u0027s probably a good idea to capture req.method and req.path *before* calling the wrapped function, just in case the wrapped function changes them. ``labeled_timing_stats`` does this for req.method, but I don\u0027t recall if we had an example of when this might happen; it might just have been very defensive.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":63,"context_line":"                        \u0027%s\u003d%.3fs\u0027 % (operation, duration))"},{"line_number":64,"context_line":"                ctrl.logger.warning("},{"line_number":65,"context_line":"                    \u0027Slow %s (%.3fs) for %s, status %d, %s\u0027,"},{"line_number":66,"context_line":"                    req.method, total_time, req.path, resp.status_int,"},{"line_number":67,"context_line":"                    \u0027, \u0027.join(timing_parts)"},{"line_number":68,"context_line":"                )"},{"line_number":69,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"b7dd089b_3f177025","line":66,"in_reply_to":"60453237_e67e6022","updated":"2025-08-20 05:30:48.000000000","message":"Done","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":72,"context_line":"    return decorating_func"},{"line_number":73,"context_line":""},{"line_number":74,"context_line":""},{"line_number":75,"context_line":"def record_slow_timing(timing_breakdown, key, timing_start):"},{"line_number":76,"context_line":"    \"\"\""},{"line_number":77,"context_line":"    Records a timing event if timing_breakdown is enabled."},{"line_number":78,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"7402304c_74f79d1f","line":75,"range":{"start_line":75,"start_character":11,"end_line":75,"end_character":16},"updated":"2025-07-04 17:48:33.000000000","message":"similar to comment about name of the decorator, there\u0027s nothing about this that is specific to *slow* timing - it is used to record *any* timings","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":72,"context_line":"    return decorating_func"},{"line_number":73,"context_line":""},{"line_number":74,"context_line":""},{"line_number":75,"context_line":"def record_slow_timing(timing_breakdown, key, timing_start):"},{"line_number":76,"context_line":"    \"\"\""},{"line_number":77,"context_line":"    Records a timing event if timing_breakdown is enabled."},{"line_number":78,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"95fe941f_b17f46d8","line":75,"range":{"start_line":75,"start_character":11,"end_line":75,"end_character":16},"in_reply_to":"7402304c_74f79d1f","updated":"2025-08-20 05:30:48.000000000","message":"Acknowledged","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":76,"context_line":"    \"\"\""},{"line_number":77,"context_line":"    Records a timing event if timing_breakdown is enabled."},{"line_number":78,"context_line":""},{"line_number":79,"context_line":"    :param timing_breakdown: A dictionary to store timing information, or None."},{"line_number":80,"context_line":"    :param key: The key under which to store the timing information."},{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."}],"source_content_type":"text/x-python","patch_set":6,"id":"224a49eb_88f53970","line":79,"range":{"start_line":79,"start_character":71,"end_line":79,"end_character":78},"updated":"2025-07-04 17:48:33.000000000","message":"in what scenario would this be None? Wouldn\u0027t it be a bug: decorated method has been given a dict, but then passed None to this method","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"d4b77ebfaba6667bf8b038d9788c9f672963ac5b","unresolved":true,"context_lines":[{"line_number":76,"context_line":"    \"\"\""},{"line_number":77,"context_line":"    Records a timing event if timing_breakdown is enabled."},{"line_number":78,"context_line":""},{"line_number":79,"context_line":"    :param timing_breakdown: A dictionary to store timing information, or None."},{"line_number":80,"context_line":"    :param key: The key under which to store the timing information."},{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."}],"source_content_type":"text/x-python","patch_set":6,"id":"4369b622_0c9fc857","line":79,"range":{"start_line":79,"start_character":71,"end_line":79,"end_character":78},"in_reply_to":"224a49eb_88f53970","updated":"2025-07-08 03:18:34.000000000","message":"this is one scenario: https://review.opendev.org/c/openstack/swift/+/953977/3/swift/obj/diskfile.py#1302\n\nA valid ``timing_breakdown`` will be passed down from object server REPLICATE(), but when ``get_hashes()`` is called in another path ``relinker.py``, ``None`` will be passed in.\n\nI think the more we use this decorator and instrument the internal functions, the more similar cases will surface.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":76,"context_line":"    \"\"\""},{"line_number":77,"context_line":"    Records a timing event if timing_breakdown is enabled."},{"line_number":78,"context_line":""},{"line_number":79,"context_line":"    :param timing_breakdown: A dictionary to store timing information, or None."},{"line_number":80,"context_line":"    :param key: The key under which to store the timing information."},{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."}],"source_content_type":"text/x-python","patch_set":6,"id":"995b2e1a_800873b3","line":79,"range":{"start_line":79,"start_character":71,"end_line":79,"end_character":78},"in_reply_to":"4369b622_0c9fc857","updated":"2025-08-20 05:30:48.000000000","message":"not relevant anymore after switching to use a new TimingBreakdown class.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":78,"context_line":""},{"line_number":79,"context_line":"    :param timing_breakdown: A dictionary to store timing information, or None."},{"line_number":80,"context_line":"    :param key: The key under which to store the timing information."},{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."},{"line_number":83,"context_line":"    \"\"\""},{"line_number":84,"context_line":"    if timing_breakdown is not None and \\"}],"source_content_type":"text/x-python","patch_set":6,"id":"3388d4a2_0b7cb99a","line":81,"updated":"2025-07-04 17:48:33.000000000","message":"just a thought: \u0027start\u0027 could be an item pre-set in the timing_breakdown dict, callers add actual times to the dict, and the time deltas are calculated when the timing breakdown is logged. That might avoid needing this helper altogether.\n\n(note: dict order is preserved, so the items will iterate in the order they were added)","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":78,"context_line":""},{"line_number":79,"context_line":"    :param timing_breakdown: A dictionary to store timing information, or None."},{"line_number":80,"context_line":"    :param key: The key under which to store the timing information."},{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."},{"line_number":83,"context_line":"    \"\"\""},{"line_number":84,"context_line":"    if timing_breakdown is not None and \\"}],"source_content_type":"text/x-python","patch_set":6,"id":"3e90d158_90e82701","line":81,"in_reply_to":"3388d4a2_0b7cb99a","updated":"2025-08-20 05:30:48.000000000","message":"After switching to the new TimingBreakdown class, there is no need for ``timing_start``.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":79,"context_line":"    :param timing_breakdown: A dictionary to store timing information, or None."},{"line_number":80,"context_line":"    :param key: The key under which to store the timing information."},{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."},{"line_number":83,"context_line":"    \"\"\""},{"line_number":84,"context_line":"    if timing_breakdown is not None and \\"},{"line_number":85,"context_line":"            isinstance(timing_breakdown, defaultdict):"}],"source_content_type":"text/x-python","patch_set":6,"id":"a8b121c1_dc0547c1","line":82,"range":{"start_line":82,"start_character":14,"end_line":82,"end_character":30},"updated":"2025-07-04 17:48:33.000000000","message":"not strictly true, if timing_breakdown is not the expected type.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":79,"context_line":"    :param timing_breakdown: A dictionary to store timing information, or None."},{"line_number":80,"context_line":"    :param key: The key under which to store the timing information."},{"line_number":81,"context_line":"    :param timing_start: The start time of the event."},{"line_number":82,"context_line":"    :returns: The current time, to be used as the next timing_start."},{"line_number":83,"context_line":"    \"\"\""},{"line_number":84,"context_line":"    if timing_breakdown is not None and \\"},{"line_number":85,"context_line":"            isinstance(timing_breakdown, defaultdict):"}],"source_content_type":"text/x-python","patch_set":6,"id":"482f5537_8cab63ba","line":82,"range":{"start_line":82,"start_character":14,"end_line":82,"end_character":30},"in_reply_to":"a8b121c1_dc0547c1","updated":"2025-08-20 05:30:48.000000000","message":"Acknowledged","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":85,"context_line":"            isinstance(timing_breakdown, defaultdict):"},{"line_number":86,"context_line":"        now \u003d time.time()"},{"line_number":87,"context_line":"        # Add the duration to the existing value for this key"},{"line_number":88,"context_line":"        timing_breakdown[key] +\u003d now - timing_start"},{"line_number":89,"context_line":"        return now"},{"line_number":90,"context_line":"    return timing_start"},{"line_number":91,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"298aad67_411f58c5","line":88,"updated":"2025-07-04 17:48:33.000000000","message":"That\u0027s interesting - what is the use case for this cumulative timing? accumulating elapsed time on something that is retried??\n\nThis does preclude the same \u0027event\u0027 being logged more than once under the same key (for example if a method has to wait for a lock multiple times it would need to record for \u0027take_lock-1\u0027, \u0027take_lock-2\u0027) etc which implies the decorated method needing to be aware of which number each event is.\n\nI was going to suggest that the timing_breakdown should be a *list of tuples* (event, time) rather than a dict, precisely so repeated events can be recorded independently, in order, using the same key. So we could have a trace like:\n\n```\ntake_lock\u003d0.1\nthing1\u003d0.01\ntake_lock\u003d0.2\nthing2\u003d123.4\n```\n\nThis could get particularly relevant if timing_breakdown is passed into another method that is called repeatedly: presumably with the dict approach we\u0027d need to pass timing_breakdown and some context to differentiate each call to the method.\n\n```\ndef submethod(timing_breakdown):\n    # do stuff\n    record_slow_timing(\u0027stuff done\u0027)\n    # do more stuff\n    record_slow_timing(\u0027more stuff done\u0027)\n```\n\nwould actually need to become\n\n```\ndef submethod(timing_breakdown, timing_breakdown_context):\n    # do stuff\n    record_slow_timing(\u0027stuff done\u0027 + timing_breakdown_context)\n    # do more stuff\n    record_slow_timing(\u0027more stuff done\u0027 + timing_breakdown_context)\n```","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"d4b77ebfaba6667bf8b038d9788c9f672963ac5b","unresolved":true,"context_lines":[{"line_number":85,"context_line":"            isinstance(timing_breakdown, defaultdict):"},{"line_number":86,"context_line":"        now \u003d time.time()"},{"line_number":87,"context_line":"        # Add the duration to the existing value for this key"},{"line_number":88,"context_line":"        timing_breakdown[key] +\u003d now - timing_start"},{"line_number":89,"context_line":"        return now"},{"line_number":90,"context_line":"    return timing_start"},{"line_number":91,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"c8c93e64_fe8c7e3c","line":88,"in_reply_to":"298aad67_411f58c5","updated":"2025-07-08 03:18:34.000000000","message":"here is the case which got me to use the cumulative timing: https://review.opendev.org/c/openstack/swift/+/953977/3/swift/obj/diskfile.py#1396\n\n``__get_hashes()`` could be called recursively.\n\n\u003e\u003e I was going to suggest that the timing_breakdown should be a list of tuples (event, time) rather than a dict, precisely so repeated events can be recorded independently, in order, using the same key.\n\nI agree, this is a better way to debug this recursive call, with repeated events being recorded independently, we could also infer that how many times it was called and how things look like for each call, awesome idea!","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"14f9fb8835a657e82f6ccebbadaa5bb31d80efe6","unresolved":false,"context_lines":[{"line_number":85,"context_line":"            isinstance(timing_breakdown, defaultdict):"},{"line_number":86,"context_line":"        now \u003d time.time()"},{"line_number":87,"context_line":"        # Add the duration to the existing value for this key"},{"line_number":88,"context_line":"        timing_breakdown[key] +\u003d now - timing_start"},{"line_number":89,"context_line":"        return now"},{"line_number":90,"context_line":"    return timing_start"},{"line_number":91,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"5cbe0ce8_9b1031c5","line":88,"in_reply_to":"923c205f_b2ba4e1a","updated":"2025-08-22 09:52:33.000000000","message":"Acknowledged","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":true,"context_lines":[{"line_number":85,"context_line":"            isinstance(timing_breakdown, defaultdict):"},{"line_number":86,"context_line":"        now \u003d time.time()"},{"line_number":87,"context_line":"        # Add the duration to the existing value for this key"},{"line_number":88,"context_line":"        timing_breakdown[key] +\u003d now - timing_start"},{"line_number":89,"context_line":"        return now"},{"line_number":90,"context_line":"    return timing_start"},{"line_number":91,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"923c205f_b2ba4e1a","line":88,"in_reply_to":"c8c93e64_fe8c7e3c","updated":"2025-08-20 05:30:48.000000000","message":"After experiments with breakdown timings logging for object-server-r delete requests and trace logging for get_hashes (https://review.opendev.org/c/openstack/swift/+/954379) on production, I feel we need two layers of logging framework to facilitate detecting and debugging various future operation slowness within the cluster:\n   1. layer 1 logging to detect slow requests and identity the bottleneck roughly. like the implementation in 951219: Object: log breakdown timings for slow DELETE requests. | https://review.opendev.org/c/openstack/swift/+/951219. There are timing breakdowns for sub-steps like ``tombstone_write``, ``tpool_scheduling`` or ``containter_update``, we can roughly identify where sub-step takes most of time for one slow request.\n   2. layer 2 logging to troubleshooting why the particular sub-step is the bottleneck, this would need dedicated new patch like \"trace logging for get_hashes\"(https://review.opendev.org/c/openstack/swift/+/954379)\n   \nConsidering that the number of slow requests per day could reach millions, having slow request logging with high-level timing breakdowns will already be very helpful for spotting performance issues and providing a general idea of where potential bottlenecks lie.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"2a7dcbf23bccf000f1f7bbd38edc0ed1435e14f7","unresolved":true,"context_lines":[{"line_number":57,"context_line":"    @property"},{"line_number":58,"context_line":"    def breakdown(self):"},{"line_number":59,"context_line":"        \"\"\""},{"line_number":60,"context_line":"        Get a dict of all recorded events and elapsed times by insertion order."},{"line_number":61,"context_line":"        \"\"\""},{"line_number":62,"context_line":"        return self._breakdown"},{"line_number":63,"context_line":""}],"source_content_type":"text/x-python","patch_set":8,"id":"9873d707_bc9f1a7b","line":60,"updated":"2025-08-21 17:20:36.000000000","message":"the dict order is determined by the *first* insertion of a key, so if record is called more than once with the same event then the order gets potentially confusing:\n\n```\n\u003e\u003e\u003e def do_it():\n...     tb \u003d TimingBreakdown()\n...     for event, elapsed in [(\u0027start\u0027, 0), (\u0027x\u0027, .11), (\u0027y\u0027, .2), (\u0027x\u0027, .3)]:\n...         time.sleep(elapsed)\n...         tb.record(event)\n...     return tb.breakdown\n...\n\u003e\u003e\u003e do_it()\n{\u0027start\u0027: 7.867813110351562e-06, \u0027x\u0027: 0.3035259246826172, \u0027y\u0027: 0.20508098602294922}\n```\n\nI wonder if a list of tuples might be better for breakdown rather than a dict?","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"ccc060d3daab125d83d66fe243907dbd527d9879","unresolved":false,"context_lines":[{"line_number":57,"context_line":"    @property"},{"line_number":58,"context_line":"    def breakdown(self):"},{"line_number":59,"context_line":"        \"\"\""},{"line_number":60,"context_line":"        Get a dict of all recorded events and elapsed times by insertion order."},{"line_number":61,"context_line":"        \"\"\""},{"line_number":62,"context_line":"        return self._breakdown"},{"line_number":63,"context_line":""}],"source_content_type":"text/x-python","patch_set":8,"id":"9aa78947_6ed6b84a","line":60,"in_reply_to":"9873d707_bc9f1a7b","updated":"2025-08-22 05:21:51.000000000","message":"I converted it to be a list of tuples, thanks for the suggestion.","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"2a7dcbf23bccf000f1f7bbd38edc0ed1435e14f7","unresolved":true,"context_lines":[{"line_number":89,"context_line":""},{"line_number":90,"context_line":"            total_time \u003d time.time() - start_time"},{"line_number":91,"context_line":"            threshold \u003d getattr(ctrl, threshold_attr)"},{"line_number":92,"context_line":"            if total_time \u003e threshold:"},{"line_number":93,"context_line":"                timing_parts \u003d []"},{"line_number":94,"context_line":"                for operation, duration in timing_breakdown.breakdown.items():"},{"line_number":95,"context_line":"                    timing_parts.append("}],"source_content_type":"text/x-python","patch_set":8,"id":"3f2399c4_fe96d369","line":92,"updated":"2025-08-21 17:20:36.000000000","message":"to disable the logs an SRE would need to set the threshold to a large number. It might be useful to have -1 interpreted as \u0027disabled\u0027","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"ccc060d3daab125d83d66fe243907dbd527d9879","unresolved":false,"context_lines":[{"line_number":89,"context_line":""},{"line_number":90,"context_line":"            total_time \u003d time.time() - start_time"},{"line_number":91,"context_line":"            threshold \u003d getattr(ctrl, threshold_attr)"},{"line_number":92,"context_line":"            if total_time \u003e threshold:"},{"line_number":93,"context_line":"                timing_parts \u003d []"},{"line_number":94,"context_line":"                for operation, duration in timing_breakdown.breakdown.items():"},{"line_number":95,"context_line":"                    timing_parts.append("}],"source_content_type":"text/x-python","patch_set":8,"id":"d232feb7_14895638","line":92,"in_reply_to":"3f2399c4_fe96d369","updated":"2025-08-22 05:21:51.000000000","message":"Done","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":true,"context_lines":[{"line_number":99,"context_line":"                ctrl.logger.warning("},{"line_number":100,"context_line":"                    \u0027Slow %s (%.3fs) for %s, status %d, start_time\u003d%.3f, %s\u0027,"},{"line_number":101,"context_line":"                    req_method, total_time, req_path, resp.status_int,"},{"line_number":102,"context_line":"                    start_time, \u0027, \u0027.join(timing_parts)"},{"line_number":103,"context_line":"                )"},{"line_number":104,"context_line":""},{"line_number":105,"context_line":"            return resp"}],"source_content_type":"text/x-python","patch_set":9,"id":"a579d7be_e92456c6","line":102,"range":{"start_line":102,"start_character":20,"end_line":102,"end_character":31},"updated":"2025-08-22 09:50:54.000000000","message":"+1 for including the start time","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"92b142e3797f668655a045485de00164a4e9c617","unresolved":false,"context_lines":[{"line_number":99,"context_line":"                ctrl.logger.warning("},{"line_number":100,"context_line":"                    \u0027Slow %s (%.3fs) for %s, status %d, start_time\u003d%.3f, %s\u0027,"},{"line_number":101,"context_line":"                    req_method, total_time, req_path, resp.status_int,"},{"line_number":102,"context_line":"                    start_time, \u0027, \u0027.join(timing_parts)"},{"line_number":103,"context_line":"                )"},{"line_number":104,"context_line":""},{"line_number":105,"context_line":"            return resp"}],"source_content_type":"text/x-python","patch_set":9,"id":"645961ca_6fd37f9f","line":102,"range":{"start_line":102,"start_character":20,"end_line":102,"end_character":31},"in_reply_to":"a579d7be_e92456c6","updated":"2025-08-23 00:04:27.000000000","message":"Acknowledged","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"49d3063d71a2d75667c60d4d56bb8e00efe3b92b","unresolved":true,"context_lines":[{"line_number":33,"context_line":"        tb.record(\u0027step1\u0027)"},{"line_number":34,"context_line":"        # ... do something else ..."},{"line_number":35,"context_line":"        tb.record(\u0027step2\u0027)"},{"line_number":36,"context_line":"        print(tb.breakdown)  # [(\u0027step1\u0027, 0.123), (\u0027step2\u0027, 0.456)]"},{"line_number":37,"context_line":"    \"\"\""},{"line_number":38,"context_line":"    def __init__(self, start_time\u003dNone):"},{"line_number":39,"context_line":"        self._breakdown \u003d []"}],"source_content_type":"text/x-python","patch_set":12,"id":"462042c7_d2e22a77","line":36,"updated":"2026-03-10 20:01:53.000000000","message":"this isn\u0027t the interface that most tracing instrumentation sdk use.  This interface conflates a measured span and a span event:\n\nhttps://opentelemetry.io/docs/concepts/signals/traces/#span-events\n\nConsider the following imaginary instrumentation\n\n```\ndef do_work(timing_breakdown):\n    step1()\n    tb.record(\u0027step1\u0027)\n    bookkeeping_should_be_fast()\n    step2()\n    tb.record(\u0027step2\u0027)\n```\n\nif `bookkeeping_should_be_fast()` turns out to be *slow* it will *look* like `step2` took a long time.  Consider why otel chose their interface:\n\n```\ndef do_work(trace):\n    with trace.span(\u0027step1\u0027):\n        step1()\n    bookkeeping_should_be_fast()\n    with trace.span(\u0027step2\u0027):\n        step2()\n```\n\nif it turns out `bookkeeping_should_be_fast` is slow that will be clear from both `step1` and `step2` being fast - despite the \"parent\" span being slow.\n\ni.e. quality metrics are intrinsic to the interface instead of dependent on careful code reading.\n\nI also think that \"nested spans\"\n\nhttps://opentelemetry.io/docs/languages/python/instrumentation/#creating-nested-spans\n\nare going to be useful if we have to troubleshooting something that is actually cpu or disk bound as opposed to just blocking on executor contention; and it provides a clear organizational structure as the requests span/trace instrumentation moves deeper into diskfile and other modules/functions.","commit_id":"9a1adb5c67fa0022ed4880c0202aca5f3d0e2b21"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"49d3063d71a2d75667c60d4d56bb8e00efe3b92b","unresolved":true,"context_lines":[{"line_number":100,"context_line":"                    \u0027Slow %s (%.3fs) for %s, status %d, start_time\u003d%.3f, %s\u0027,"},{"line_number":101,"context_line":"                    req_method, total_time, req_path, resp.status_int,"},{"line_number":102,"context_line":"                    start_time, \u0027, \u0027.join(timing_parts)"},{"line_number":103,"context_line":"                )"},{"line_number":104,"context_line":""},{"line_number":105,"context_line":"            return resp"},{"line_number":106,"context_line":"        return _request_timing_logging"}],"source_content_type":"text/x-python","patch_set":12,"id":"a540f32a_a0fab4b6","line":103,"updated":"2026-03-10 20:01:53.000000000","message":"I don\u0027t find this formatting particularly easy to parse/process - it might be more useful as:\n\n```\nEASY_TO_FIND_WITH_REGEX\u003cjson\u003e\n```\n\n... unless the intention is that this warning is mostly for humans, and then maybe that\u0027s fine.","commit_id":"9a1adb5c67fa0022ed4880c0202aca5f3d0e2b21"}],"test/unit/common/test_base_storage_server.py":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5a4cb22b4fcae0a91557e1ba77f8ec1900903cbc","unresolved":true,"context_lines":[{"line_number":401,"context_line":"        self.assertEqual(new_start, timing_start)"},{"line_number":402,"context_line":""},{"line_number":403,"context_line":"    def test_new_key(self):"},{"line_number":404,"context_line":"        timing_breakdown \u003d defaultdict(float)"},{"line_number":405,"context_line":"        now \u003d time.time()"},{"line_number":406,"context_line":"        with mock.patch(\u0027time.time\u0027, side_effect\u003d[now + 1.5]):"},{"line_number":407,"context_line":"            timing_start \u003d now"}],"source_content_type":"text/x-python","patch_set":5,"id":"dcfd261a_7d124433","line":404,"updated":"2025-07-03 01:51:05.000000000","message":"Do we want to test where timing_breakdown isn\u0027t None or a Dict to see what happens. Incase the wrong thing is passed in?","commit_id":"80f8b5418bbdda3cd00d0c7161edeb02581d0e28"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"bc6f1da524dbf948e05a8bf2a366437587b74610","unresolved":false,"context_lines":[{"line_number":401,"context_line":"        self.assertEqual(new_start, timing_start)"},{"line_number":402,"context_line":""},{"line_number":403,"context_line":"    def test_new_key(self):"},{"line_number":404,"context_line":"        timing_breakdown \u003d defaultdict(float)"},{"line_number":405,"context_line":"        now \u003d time.time()"},{"line_number":406,"context_line":"        with mock.patch(\u0027time.time\u0027, side_effect\u003d[now + 1.5]):"},{"line_number":407,"context_line":"            timing_start \u003d now"}],"source_content_type":"text/x-python","patch_set":5,"id":"e5eb0b03_75ede57d","line":404,"in_reply_to":"dcfd261a_7d124433","updated":"2025-07-03 19:20:42.000000000","message":"Done","commit_id":"80f8b5418bbdda3cd00d0c7161edeb02581d0e28"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":232,"context_line":""},{"line_number":233,"context_line":"            @slow_request_logging(threshold_attr\u003d\u0027slow_threshold\u0027)"},{"line_number":234,"context_line":"            def handle_slow_req(self, req, timing_breakdown):"},{"line_number":235,"context_line":"                timing_breakdown[\u0027operation_1\u0027] \u003d 0.011"},{"line_number":236,"context_line":"                timing_breakdown[\u0027operation_2\u0027] \u003d 0.07"},{"line_number":237,"context_line":"                timing_breakdown[\u0027operation_3\u0027] \u003d 0.02"},{"line_number":238,"context_line":"                return Response(status\u003dself.status)"}],"source_content_type":"text/x-python","patch_set":6,"id":"3974c741_e5c5dc07","line":235,"updated":"2025-07-04 17:48:33.000000000","message":"just thinking about the interface: these tests suggest that the decorated method is measuring time deltas that it just sets in the dict - but that\u0027s not likely the case, and in practice decorated functions will need to be modified to track time deltas...which is where the ``record_slow_timing`` helper comes in, but that still leaves the decorated method needing to manage the ``timing_start`` variable","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":232,"context_line":""},{"line_number":233,"context_line":"            @slow_request_logging(threshold_attr\u003d\u0027slow_threshold\u0027)"},{"line_number":234,"context_line":"            def handle_slow_req(self, req, timing_breakdown):"},{"line_number":235,"context_line":"                timing_breakdown[\u0027operation_1\u0027] \u003d 0.011"},{"line_number":236,"context_line":"                timing_breakdown[\u0027operation_2\u0027] \u003d 0.07"},{"line_number":237,"context_line":"                timing_breakdown[\u0027operation_3\u0027] \u003d 0.02"},{"line_number":238,"context_line":"                return Response(status\u003dself.status)"}],"source_content_type":"text/x-python","patch_set":6,"id":"12f77f41_b708e33b","line":235,"in_reply_to":"3974c741_e5c5dc07","updated":"2025-08-20 05:30:48.000000000","message":"``record_slow_timing`` helper is converted to a helper class which won\u0027t need ``timing_start`` anymore.","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":304,"context_line":"                self.logger \u003d debug_logger()"},{"line_number":305,"context_line":""},{"line_number":306,"context_line":"            # No threshold_attr attribute, the default threshold is used."},{"line_number":307,"context_line":"            @slow_request_logging()"},{"line_number":308,"context_line":"            def handle_req(self, req, timing_breakdown):"},{"line_number":309,"context_line":"                timing_breakdown[\u0027operation_1\u0027] \u003d 59.0"},{"line_number":310,"context_line":"                return Response(status\u003dself.status)"}],"source_content_type":"text/x-python","patch_set":6,"id":"eef7d638_3190e6a8","line":307,"range":{"start_line":307,"start_character":12,"end_line":307,"end_character":35},"updated":"2025-07-04 17:48:33.000000000","message":"why isn\u0027t this just considered a bug?\n\nwhat stopped the dev adding ``self.my_threshold_attr`` \u003d 60 in the ``__init__``?","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":304,"context_line":"                self.logger \u003d debug_logger()"},{"line_number":305,"context_line":""},{"line_number":306,"context_line":"            # No threshold_attr attribute, the default threshold is used."},{"line_number":307,"context_line":"            @slow_request_logging()"},{"line_number":308,"context_line":"            def handle_req(self, req, timing_breakdown):"},{"line_number":309,"context_line":"                timing_breakdown[\u0027operation_1\u0027] \u003d 59.0"},{"line_number":310,"context_line":"                return Response(status\u003dself.status)"}],"source_content_type":"text/x-python","patch_set":6,"id":"e2e1ad70_15122eea","line":307,"range":{"start_line":307,"start_character":12,"end_line":307,"end_character":35},"in_reply_to":"eef7d638_3190e6a8","updated":"2025-08-20 05:30:48.000000000","message":"Acknowledged","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":338,"context_line":"                self.status \u003d status"},{"line_number":339,"context_line":"                self.logger \u003d debug_logger()"},{"line_number":340,"context_line":""},{"line_number":341,"context_line":"            @slow_request_logging(threshold_attr\u003d\u0027slow_threshold\u0027)"},{"line_number":342,"context_line":"            def handle_req(self, req, timing_breakdown):"},{"line_number":343,"context_line":"                timing_breakdown[\u0027operation_1\u0027] \u003d 59.0"},{"line_number":344,"context_line":"                return Response(status\u003dself.status)"}],"source_content_type":"text/x-python","patch_set":6,"id":"2a54cbe2_9ba36df1","line":341,"range":{"start_line":341,"start_character":12,"end_line":341,"end_character":66},"updated":"2025-07-04 17:48:33.000000000","message":"ditto, why isn\u0027t this just considered a bug?","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":338,"context_line":"                self.status \u003d status"},{"line_number":339,"context_line":"                self.logger \u003d debug_logger()"},{"line_number":340,"context_line":""},{"line_number":341,"context_line":"            @slow_request_logging(threshold_attr\u003d\u0027slow_threshold\u0027)"},{"line_number":342,"context_line":"            def handle_req(self, req, timing_breakdown):"},{"line_number":343,"context_line":"                timing_breakdown[\u0027operation_1\u0027] \u003d 59.0"},{"line_number":344,"context_line":"                return Response(status\u003dself.status)"}],"source_content_type":"text/x-python","patch_set":6,"id":"d6e7afed_fb0dd8c6","line":341,"range":{"start_line":341,"start_character":12,"end_line":341,"end_character":66},"in_reply_to":"2a54cbe2_9ba36df1","updated":"2025-08-20 05:30:48.000000000","message":"Acknowledged","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"33ddb814297928880d804d4e0e54f2b42e3ee48c","unresolved":true,"context_lines":[{"line_number":404,"context_line":"        timing_breakdown \u003d []"},{"line_number":405,"context_line":"        timing_start \u003d 1000.0"},{"line_number":406,"context_line":"        new_start \u003d record_slow_timing("},{"line_number":407,"context_line":"            timing_breakdown, \u0027test_key\u0027, timing_start)"},{"line_number":408,"context_line":"        self.assertEqual(timing_breakdown, [])"},{"line_number":409,"context_line":"        self.assertEqual(new_start, timing_start)"},{"line_number":410,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"aaa77456_1a1f8174","line":407,"updated":"2025-07-04 17:48:33.000000000","message":"this would just be a bug I think?","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"1178f170b95b6ba5ef7e709305706eca876f65b2","unresolved":false,"context_lines":[{"line_number":404,"context_line":"        timing_breakdown \u003d []"},{"line_number":405,"context_line":"        timing_start \u003d 1000.0"},{"line_number":406,"context_line":"        new_start \u003d record_slow_timing("},{"line_number":407,"context_line":"            timing_breakdown, \u0027test_key\u0027, timing_start)"},{"line_number":408,"context_line":"        self.assertEqual(timing_breakdown, [])"},{"line_number":409,"context_line":"        self.assertEqual(new_start, timing_start)"},{"line_number":410,"context_line":""}],"source_content_type":"text/x-python","patch_set":6,"id":"b612e8d1_c14867d9","line":407,"in_reply_to":"aaa77456_1a1f8174","updated":"2025-08-20 05:30:48.000000000","message":"Acknowledged","commit_id":"00fd734b25bb5eec1653b86df1c606a20221efc4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"2a7dcbf23bccf000f1f7bbd38edc0ed1435e14f7","unresolved":true,"context_lines":[{"line_number":262,"context_line":"        with mock.patch(\u0027time.time\u0027, side_effect\u003d[1001.0, 1002.5]):"},{"line_number":263,"context_line":"            tb.record(\u0027event1\u0027)"},{"line_number":264,"context_line":"            tb.record(\u0027event1\u0027)  # Same key again"},{"line_number":265,"context_line":"        self.assertEqual(tb.breakdown, {\u0027event1\u0027: 1.5})"},{"line_number":266,"context_line":""},{"line_number":267,"context_line":"    def test_zero_elapsed_time(self):"},{"line_number":268,"context_line":"        tb \u003d TimingBreakdown(start_time\u003d1000.0)"}],"source_content_type":"text/x-python","patch_set":8,"id":"bf5793bf_ded09141","line":265,"updated":"2025-08-21 17:20:36.000000000","message":"ok, this is what I was concerned about in my comment in base_storage_server.py:\n\n1. information is lost when there is an overwrite\n2. ordering is misrepresented when there is an overwrite","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"ccc060d3daab125d83d66fe243907dbd527d9879","unresolved":false,"context_lines":[{"line_number":262,"context_line":"        with mock.patch(\u0027time.time\u0027, side_effect\u003d[1001.0, 1002.5]):"},{"line_number":263,"context_line":"            tb.record(\u0027event1\u0027)"},{"line_number":264,"context_line":"            tb.record(\u0027event1\u0027)  # Same key again"},{"line_number":265,"context_line":"        self.assertEqual(tb.breakdown, {\u0027event1\u0027: 1.5})"},{"line_number":266,"context_line":""},{"line_number":267,"context_line":"    def test_zero_elapsed_time(self):"},{"line_number":268,"context_line":"        tb \u003d TimingBreakdown(start_time\u003d1000.0)"}],"source_content_type":"text/x-python","patch_set":8,"id":"bddd1a35_ceaddbe4","line":265,"in_reply_to":"bf5793bf_ded09141","updated":"2025-08-22 05:21:51.000000000","message":"Done","commit_id":"92542e7c31003021aa49faed40ebe29c32a33ed7"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":true,"context_lines":[{"line_number":384,"context_line":""},{"line_number":385,"context_line":"        # Should not log any warnings despite very slow operation"},{"line_number":386,"context_line":"        error_lines \u003d controller.logger.get_lines_for_level(\u0027warning\u0027)"},{"line_number":387,"context_line":"        self.assertEqual(0, len(error_lines))"},{"line_number":388,"context_line":""},{"line_number":389,"context_line":"    def test_zero_threshold_logs_everything(self):"},{"line_number":390,"context_line":""}],"source_content_type":"text/x-python","patch_set":9,"id":"db055477_5bd80523","line":387,"updated":"2025-08-22 09:50:54.000000000","message":"nit: if this assertion fails the message isn\u0027t very informative\n\n```\nE   AssertionError: 0 !\u003d 1\n```\n\nif we use ``self.assertFalse(error_lines)`` then we\u0027d get more information if the assertion fails\n\n```\nE   AssertionError: [\u0027Slow GET (20.000s) for /v1/a/c/o, status 200, start_time\u003d1000.000, operation_1\u003d5.000s, operation_2\u003d10.000s\u0027] is not false\n```\n\nsame at line 358\n\neither the way the test fails when I change slow_threshold 😊","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"92b142e3797f668655a045485de00164a4e9c617","unresolved":false,"context_lines":[{"line_number":384,"context_line":""},{"line_number":385,"context_line":"        # Should not log any warnings despite very slow operation"},{"line_number":386,"context_line":"        error_lines \u003d controller.logger.get_lines_for_level(\u0027warning\u0027)"},{"line_number":387,"context_line":"        self.assertEqual(0, len(error_lines))"},{"line_number":388,"context_line":""},{"line_number":389,"context_line":"    def test_zero_threshold_logs_everything(self):"},{"line_number":390,"context_line":""}],"source_content_type":"text/x-python","patch_set":9,"id":"83a2e351_35132520","line":387,"in_reply_to":"db055477_5bd80523","updated":"2025-08-23 00:04:27.000000000","message":"Done","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":true,"context_lines":[{"line_number":413,"context_line":"        self.assertEqual(1, len(error_lines))"},{"line_number":414,"context_line":"        self.assertEqual(\u0027Slow GET (0.002s) for /v1/a/c/o, status 200, \u0027"},{"line_number":415,"context_line":"                         \u0027start_time\u003d1000.000, operation_1\u003d0.001s\u0027,"},{"line_number":416,"context_line":"                         error_lines[0])"},{"line_number":417,"context_line":""},{"line_number":418,"context_line":"    def test_no_slow_threshold_attr(self):"},{"line_number":419,"context_line":""}],"source_content_type":"text/x-python","patch_set":9,"id":"39c52867_246675d1","line":416,"updated":"2025-08-22 09:50:54.000000000","message":"ok! if I increase slow_threshold the test will fail\n\n```\nE   AssertionError: 1 !\u003d 0\n```\n\nand also fails with\n```\ndiff --git a/swift/common/base_storage_server.py b/swift/common/base_storage_server.py\nindex 5e9f693ae..ea9a512d0 100644\n--- a/swift/common/base_storage_server.py\n+++ b/swift/common/base_storage_server.py\n@@ -91,7 +91,7 @@ def request_timing_logging(threshold_attr):\n \n             total_time \u003d time.time() - start_time\n             threshold \u003d getattr(ctrl, threshold_attr)\n-            if threshold !\u003d -1 and total_time \u003e threshold:\n+            if threshold \u003e 0 and total_time \u003e threshold:\n                 timing_parts \u003d []\n                 for operation, duration in timing_breakdown.breakdown:\n                     timing_parts.append(\n\n```","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"92b142e3797f668655a045485de00164a4e9c617","unresolved":false,"context_lines":[{"line_number":413,"context_line":"        self.assertEqual(1, len(error_lines))"},{"line_number":414,"context_line":"        self.assertEqual(\u0027Slow GET (0.002s) for /v1/a/c/o, status 200, \u0027"},{"line_number":415,"context_line":"                         \u0027start_time\u003d1000.000, operation_1\u003d0.001s\u0027,"},{"line_number":416,"context_line":"                         error_lines[0])"},{"line_number":417,"context_line":""},{"line_number":418,"context_line":"    def test_no_slow_threshold_attr(self):"},{"line_number":419,"context_line":""}],"source_content_type":"text/x-python","patch_set":9,"id":"e8660d37_49d0d2c3","line":416,"in_reply_to":"39c52867_246675d1","updated":"2025-08-23 00:04:27.000000000","message":"Acknowledged","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":true,"context_lines":[{"line_number":430,"context_line":"        controller \u003d NormalController(200)"},{"line_number":431,"context_line":"        with self.assertRaises(TypeError):"},{"line_number":432,"context_line":"            # Decorator is applied without threshold_attr"},{"line_number":433,"context_line":"            _ \u003d request_timing_logging()(controller.handle_req)"},{"line_number":434,"context_line":""},{"line_number":435,"context_line":"    def test_missing_threshold_value(self):"},{"line_number":436,"context_line":""}],"source_content_type":"text/x-python","patch_set":9,"id":"ab220282_81c0b462","line":433,"updated":"2025-08-22 09:50:54.000000000","message":"ok, so you had to write it this way rather than apply the decorator to the function ``def`` because the TypeError would be raised when the class was loaded. Possibly overkill testing but no harm!","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"92b142e3797f668655a045485de00164a4e9c617","unresolved":false,"context_lines":[{"line_number":430,"context_line":"        controller \u003d NormalController(200)"},{"line_number":431,"context_line":"        with self.assertRaises(TypeError):"},{"line_number":432,"context_line":"            # Decorator is applied without threshold_attr"},{"line_number":433,"context_line":"            _ \u003d request_timing_logging()(controller.handle_req)"},{"line_number":434,"context_line":""},{"line_number":435,"context_line":"    def test_missing_threshold_value(self):"},{"line_number":436,"context_line":""}],"source_content_type":"text/x-python","patch_set":9,"id":"8c19798b_48047cbd","line":433,"in_reply_to":"ab220282_81c0b462","updated":"2025-08-23 00:04:27.000000000","message":"Acknowledged","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":true,"context_lines":[{"line_number":454,"context_line":"        with self.assertRaises(AttributeError):"},{"line_number":455,"context_line":"            controller.handle_req(req)"},{"line_number":456,"context_line":""},{"line_number":457,"context_line":"    def test_slow_operation_with_exception(self):"},{"line_number":458,"context_line":""},{"line_number":459,"context_line":"        class SlowExceptionController(object):"},{"line_number":460,"context_line":"            slow_threshold \u003d 0.1"}],"source_content_type":"text/x-python","patch_set":9,"id":"406c720c_31ccac98","line":457,"updated":"2025-08-22 09:50:54.000000000","message":"this is a good test to have!","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"92b142e3797f668655a045485de00164a4e9c617","unresolved":false,"context_lines":[{"line_number":454,"context_line":"        with self.assertRaises(AttributeError):"},{"line_number":455,"context_line":"            controller.handle_req(req)"},{"line_number":456,"context_line":""},{"line_number":457,"context_line":"    def test_slow_operation_with_exception(self):"},{"line_number":458,"context_line":""},{"line_number":459,"context_line":"        class SlowExceptionController(object):"},{"line_number":460,"context_line":"            slow_threshold \u003d 0.1"}],"source_content_type":"text/x-python","patch_set":9,"id":"709447cc_39a2fa00","line":457,"in_reply_to":"406c720c_31ccac98","updated":"2025-08-23 00:04:27.000000000","message":"Acknowledged","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":true,"context_lines":[{"line_number":476,"context_line":"            controller.handle_req(req)"},{"line_number":477,"context_line":""},{"line_number":478,"context_line":"        error_lines \u003d controller.logger.get_lines_for_level(\u0027warning\u0027)"},{"line_number":479,"context_line":"        self.assertEqual(1, len(error_lines))"},{"line_number":480,"context_line":"        self.assertEqual(\u0027Slow GET (0.150s) for /v1/a/c/o, status 507, \u0027"},{"line_number":481,"context_line":"                         \u0027start_time\u003d1000.000, before_error\u003d0.050s\u0027,"},{"line_number":482,"context_line":"                         error_lines[0])"}],"source_content_type":"text/x-python","patch_set":9,"id":"601bd9bd_d01a6f7f","line":479,"updated":"2025-08-22 09:50:54.000000000","message":"nit: this assertion isn\u0027t necessary if you make the next one assert the equality of the lists, which has the advantage of being more helpful if the tests ever fails because someone adds another warning. For example, this change:\n\n```\ndiff --git a/test/unit/common/test_base_storage_server.py b/test/unit/common/test_base_storage_server.py\nindex 95b45a52f..ee9155e7e 100644\n--- a/test/unit/common/test_base_storage_server.py\n+++ b/test/unit/common/test_base_storage_server.py\n@@ -467,6 +467,7 @@ class TestRequestTimingLoggingDecorator(unittest.TestCase):\n             def handle_req(self, req, timing_breakdown):\n                 # Simulate operation before error\n                 timing_breakdown.record(\u0027before_error\u0027)  # 0.05s\n+                self.logger.warning(\u0027my new warning\u0027)\n                 raise HTTPInsufficientStorage()\n \n         req \u003d Request.blank(\u0027/v1/a/c/o\u0027)\n@@ -476,10 +477,9 @@ class TestRequestTimingLoggingDecorator(unittest.TestCase):\n             controller.handle_req(req)\n \n         error_lines \u003d controller.logger.get_lines_for_level(\u0027warning\u0027)\n-        self.assertEqual(1, len(error_lines))\n-        self.assertEqual(\u0027Slow GET (0.150s) for /v1/a/c/o, status 507, \u0027\n-                         \u0027start_time\u003d1000.000, before_error\u003d0.050s\u0027,\n-                         error_lines[0])\n+        self.assertEqual([\u0027Slow GET (0.150s) for /v1/a/c/o, status 507, \u0027\n+                         \u0027start_time\u003d1000.000, before_error\u003d0.050s\u0027],\n+                         error_lines)\n \n     def test_slow_operation_with_duplicate_events(self):\n \n\n```\n\nresults in this immediate heads-up failure:\n```\n[\u0027my new warning\u0027,\n \u0027Slow GET (0.150s) for /v1/a/c/o, status 507, start_time\u003d1000.000, \u0027\n \u0027before_error\u003d0.050s\u0027] !\u003d [\u0027Slow GET (0.150s) for /v1/a/c/o, status 507, start_time\u003d1000.000, \u0027\n \u0027before_error\u003d0.050s\u0027]\n```\n\nrather than \n```\nAssertionError: 1 !\u003d 2\n```\n\nSame applies in some other tests.","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"92b142e3797f668655a045485de00164a4e9c617","unresolved":false,"context_lines":[{"line_number":476,"context_line":"            controller.handle_req(req)"},{"line_number":477,"context_line":""},{"line_number":478,"context_line":"        error_lines \u003d controller.logger.get_lines_for_level(\u0027warning\u0027)"},{"line_number":479,"context_line":"        self.assertEqual(1, len(error_lines))"},{"line_number":480,"context_line":"        self.assertEqual(\u0027Slow GET (0.150s) for /v1/a/c/o, status 507, \u0027"},{"line_number":481,"context_line":"                         \u0027start_time\u003d1000.000, before_error\u003d0.050s\u0027,"},{"line_number":482,"context_line":"                         error_lines[0])"}],"source_content_type":"text/x-python","patch_set":9,"id":"eed85f0f_a005cbba","line":479,"in_reply_to":"601bd9bd_d01a6f7f","updated":"2025-08-23 00:04:27.000000000","message":"Done","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"3eeb7c2429f52a00d08c51538ef74f660e13f775","unresolved":true,"context_lines":[{"line_number":513,"context_line":"        self.assertEqual(\u0027Slow GET (0.110s) for /v1/a/c/o, status 200, \u0027"},{"line_number":514,"context_line":"                         \u0027start_time\u003d1000.000, db_query\u003d0.030s, \u0027"},{"line_number":515,"context_line":"                         \u0027cache_check\u003d0.020s, db_query\u003d0.040s\u0027,"},{"line_number":516,"context_line":"                         error_lines[0])"},{"line_number":517,"context_line":""},{"line_number":518,"context_line":""},{"line_number":519,"context_line":"class TestTimingStatsDecorators(unittest.TestCase):"}],"source_content_type":"text/x-python","patch_set":9,"id":"52b739ac_fab7f84f","line":516,"updated":"2025-08-22 09:50:54.000000000","message":"great!","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"},{"author":{"_account_id":34930,"name":"Jianjian Huo","email":"jhuo@nvidia.com","username":"jhuo"},"change_message_id":"92b142e3797f668655a045485de00164a4e9c617","unresolved":false,"context_lines":[{"line_number":513,"context_line":"        self.assertEqual(\u0027Slow GET (0.110s) for /v1/a/c/o, status 200, \u0027"},{"line_number":514,"context_line":"                         \u0027start_time\u003d1000.000, db_query\u003d0.030s, \u0027"},{"line_number":515,"context_line":"                         \u0027cache_check\u003d0.020s, db_query\u003d0.040s\u0027,"},{"line_number":516,"context_line":"                         error_lines[0])"},{"line_number":517,"context_line":""},{"line_number":518,"context_line":""},{"line_number":519,"context_line":"class TestTimingStatsDecorators(unittest.TestCase):"}],"source_content_type":"text/x-python","patch_set":9,"id":"f0b2b6d4_c7e89744","line":516,"in_reply_to":"52b739ac_fab7f84f","updated":"2025-08-23 00:04:27.000000000","message":"Acknowledged","commit_id":"1066e05a5dfd611f2f763c2ecea27cd6d60e9c1b"}]}