)]}'
{"/COMMIT_MSG":[{"author":{"_account_id":27654,"name":"Hongbin Lu","email":"kira034@163.com","username":"hongbin.lu"},"change_message_id":"9ee9f8982c88d782280357a83a921f2e54b941c6","unresolved":false,"context_lines":[{"line_number":4,"context_line":"Commit:     LIU Yulong \u003ci@liuyulong.me\u003e"},{"line_number":5,"context_line":"CommitDate: 2019-07-07 10:44:26 +0800"},{"line_number":6,"context_line":""},{"line_number":7,"context_line":"Add a common timecost wrapper"},{"line_number":8,"context_line":""},{"line_number":9,"context_line":"And set it to all the L3 RPC functions. Move to neutron-lib"},{"line_number":10,"context_line":"if it will be widely used corss other projects."}],"source_content_type":"text/x-gerrit-commit-message","patch_set":4,"id":"7faddb67_5be60019","line":7,"range":{"start_line":7,"start_character":0,"end_line":7,"end_character":29},"updated":"2019-07-07 18:02:47.000000000","message":"I think neutron (and most of other openstack projects) uses existing tools to achieve the same goal. The most common used one is osprofiler: https://github.com/openstack/osprofiler .\n\nMy question is how this utils is different from osprofiler?","commit_id":"6a2e4b0d6080eddff41ee353eb654f26e8ed00fe"},{"author":{"_account_id":9531,"name":"liuyulong","display_name":"LIU Yulong","email":"i@liuyulong.me","username":"LIU-Yulong"},"change_message_id":"949b3c7385f8ac8320631719041fb3ea3cf598f5","unresolved":false,"context_lines":[{"line_number":4,"context_line":"Commit:     LIU Yulong \u003ci@liuyulong.me\u003e"},{"line_number":5,"context_line":"CommitDate: 2019-07-07 10:44:26 +0800"},{"line_number":6,"context_line":""},{"line_number":7,"context_line":"Add a common timecost wrapper"},{"line_number":8,"context_line":""},{"line_number":9,"context_line":"And set it to all the L3 RPC functions. Move to neutron-lib"},{"line_number":10,"context_line":"if it will be widely used corss other projects."}],"source_content_type":"text/x-gerrit-commit-message","patch_set":4,"id":"7faddb67_b62ce947","line":7,"range":{"start_line":7,"start_character":0,"end_line":7,"end_character":29},"in_reply_to":"7faddb67_5be60019","updated":"2019-07-08 01:09:28.000000000","message":"Good to know that project, thanks Hongbin. According to the user guide here: https://docs.openstack.org/osprofiler/latest/user/api.html\nIMO, this is totally different from osprofiler.\n1. You may consider this change just adds two log entries for each RPC, and neutron has many such similar log now.\n2. We do not need any trace point or call stack profile for now, it looks difficult to use (maybe I\u0027m missing something).\n3. And for upstream CI, this visual log output will make us more easily to find the time-consuming RPC by logstash. We can not download all trace profile and analyse locally.","commit_id":"6a2e4b0d6080eddff41ee353eb654f26e8ed00fe"},{"author":{"_account_id":13995,"name":"Nate Johnston","email":"nate.johnston@redhat.com","username":"natejohnston"},"change_message_id":"a35c2165e08ade4fefab46bca59e875e1ca65859","unresolved":false,"context_lines":[{"line_number":4,"context_line":"Commit:     LIU Yulong \u003ci@liuyulong.me\u003e"},{"line_number":5,"context_line":"CommitDate: 2019-07-07 10:44:26 +0800"},{"line_number":6,"context_line":""},{"line_number":7,"context_line":"Add a common timecost wrapper"},{"line_number":8,"context_line":""},{"line_number":9,"context_line":"And set it to all the L3 RPC functions. Move to neutron-lib"},{"line_number":10,"context_line":"if it will be widely used corss other projects."}],"source_content_type":"text/x-gerrit-commit-message","patch_set":4,"id":"7faddb67_164ffdbd","line":7,"range":{"start_line":7,"start_character":0,"end_line":7,"end_character":29},"in_reply_to":"7faddb67_b62ce947","updated":"2019-07-08 02:09:13.000000000","message":"I agree with Liu\u0027s points above, and in addition osprofiler adds overhead that would rule it out in production load situations.  This could be used with live load as a diagnostic tool, and I think it\u0027s very important to have that capability.","commit_id":"6a2e4b0d6080eddff41ee353eb654f26e8ed00fe"},{"author":{"_account_id":11975,"name":"Slawek Kaplonski","email":"skaplons@redhat.com","username":"slaweq"},"change_message_id":"3cc78bf9acb4825288b62a244236e140e10e9d66","unresolved":false,"context_lines":[{"line_number":7,"context_line":"Add a common timecost wrapper"},{"line_number":8,"context_line":""},{"line_number":9,"context_line":"And set it to all the L3 RPC functions. Move to neutron-lib"},{"line_number":10,"context_line":"if it will be widely used corss other projects."},{"line_number":11,"context_line":""},{"line_number":12,"context_line":"Related-Bug: #1835663"},{"line_number":13,"context_line":"Change-Id: Ie7743db097fd45df432af341470336d6a5662c6f"}],"source_content_type":"text/x-gerrit-commit-message","patch_set":8,"id":"7faddb67_f1950834","line":10,"range":{"start_line":10,"start_character":26,"end_line":10,"end_character":31},"updated":"2019-07-16 08:39:18.000000000","message":"nit: across maybe?","commit_id":"9c4bd4bd9a718d17973a9962397243c5a3d107b1"}],"neutron/common/utils.py":[{"author":{"_account_id":11975,"name":"Slawek Kaplonski","email":"skaplons@redhat.com","username":"slaweq"},"change_message_id":"2fa6467d13e16953fc508746f281dae39ca15765","unresolved":false,"context_lines":[{"line_number":924,"context_line":""},{"line_number":925,"context_line":"    def wrapper(*args, **kwargs):"},{"line_number":926,"context_line":"        call_id \u003d uuidutils.generate_uuid()"},{"line_number":927,"context_line":"        LOG.debug(\"Call %(call_id)s RPC %(fname)s start\","},{"line_number":928,"context_line":"                  {\"call_id\": call_id, \"fname\": f.__name__})"},{"line_number":929,"context_line":"        start \u003d time.time()"},{"line_number":930,"context_line":"        ret \u003d f(*args, **kwargs)"}],"source_content_type":"text/x-python","patch_set":4,"id":"7faddb67_3e4d2f72","line":927,"range":{"start_line":927,"start_character":36,"end_line":927,"end_character":39},"updated":"2019-07-08 07:13:40.000000000","message":"nit: decorator name don\u0027t say anything about using this only to RPC methods so someone may use it to decorate some other function and this RPC will be than misleading.\nMaybe You should change this log message or name of decorator to something like \"rpc_call_timecost\". What do You think?","commit_id":"6a2e4b0d6080eddff41ee353eb654f26e8ed00fe"},{"author":{"_account_id":9531,"name":"liuyulong","display_name":"LIU Yulong","email":"i@liuyulong.me","username":"LIU-Yulong"},"change_message_id":"0a9743da9ace151b2d7c6fb2326726363be79681","unresolved":false,"context_lines":[{"line_number":924,"context_line":""},{"line_number":925,"context_line":"    def wrapper(*args, **kwargs):"},{"line_number":926,"context_line":"        call_id \u003d uuidutils.generate_uuid()"},{"line_number":927,"context_line":"        LOG.debug(\"Call %(call_id)s RPC %(fname)s start\","},{"line_number":928,"context_line":"                  {\"call_id\": call_id, \"fname\": f.__name__})"},{"line_number":929,"context_line":"        start \u003d time.time()"},{"line_number":930,"context_line":"        ret \u003d f(*args, **kwargs)"}],"source_content_type":"text/x-python","patch_set":4,"id":"7faddb67_c3bbccc1","line":927,"range":{"start_line":927,"start_character":36,"end_line":927,"end_character":39},"in_reply_to":"7faddb67_3e4d2f72","updated":"2019-07-09 08:24:35.000000000","message":"Add a \u0027Time-cost:\u0027 prefix for these log.","commit_id":"6a2e4b0d6080eddff41ee353eb654f26e8ed00fe"},{"author":{"_account_id":11975,"name":"Slawek Kaplonski","email":"skaplons@redhat.com","username":"slaweq"},"change_message_id":"2fa6467d13e16953fc508746f281dae39ca15765","unresolved":false,"context_lines":[{"line_number":929,"context_line":"        start \u003d time.time()"},{"line_number":930,"context_line":"        ret \u003d f(*args, **kwargs)"},{"line_number":931,"context_line":"        end \u003d time.time() - start"},{"line_number":932,"context_line":"        LOG.debug(\"Call %(call_id)s RPC %(fname)s cost %(time).3fs\","},{"line_number":933,"context_line":"                  {\"call_id\": call_id, \"fname\": f.__name__,"},{"line_number":934,"context_line":"                   \"time\": end})"},{"line_number":935,"context_line":"        return ret"}],"source_content_type":"text/x-python","patch_set":4,"id":"7faddb67_1e5cf323","line":932,"range":{"start_line":932,"start_character":36,"end_line":932,"end_character":39},"updated":"2019-07-08 07:13:40.000000000","message":"same here","commit_id":"6a2e4b0d6080eddff41ee353eb654f26e8ed00fe"},{"author":{"_account_id":9531,"name":"liuyulong","display_name":"LIU Yulong","email":"i@liuyulong.me","username":"LIU-Yulong"},"change_message_id":"0a9743da9ace151b2d7c6fb2326726363be79681","unresolved":false,"context_lines":[{"line_number":929,"context_line":"        start \u003d time.time()"},{"line_number":930,"context_line":"        ret \u003d f(*args, **kwargs)"},{"line_number":931,"context_line":"        end \u003d time.time() - start"},{"line_number":932,"context_line":"        LOG.debug(\"Call %(call_id)s RPC %(fname)s cost %(time).3fs\","},{"line_number":933,"context_line":"                  {\"call_id\": call_id, \"fname\": f.__name__,"},{"line_number":934,"context_line":"                   \"time\": end})"},{"line_number":935,"context_line":"        return ret"}],"source_content_type":"text/x-python","patch_set":4,"id":"7faddb67_e3acc88d","line":932,"range":{"start_line":932,"start_character":36,"end_line":932,"end_character":39},"in_reply_to":"7faddb67_1e5cf323","updated":"2019-07-09 08:24:35.000000000","message":"Done","commit_id":"6a2e4b0d6080eddff41ee353eb654f26e8ed00fe"},{"author":{"_account_id":16688,"name":"Rodolfo Alonso","email":"ralonsoh@redhat.com","username":"rodolfo-alonso-hernandez"},"change_message_id":"1f9011b70bd1d26a520b0f42595ad88a45d78b55","unresolved":false,"context_lines":[{"line_number":920,"context_line":"        return (datetime.datetime.now() - self.start).total_seconds()"},{"line_number":921,"context_line":""},{"line_number":922,"context_line":""},{"line_number":923,"context_line":"def timecost(f):"},{"line_number":924,"context_line":""},{"line_number":925,"context_line":"    def wrapper(*args, **kwargs):"},{"line_number":926,"context_line":"        call_id \u003d uuidutils.generate_uuid()"}],"source_content_type":"text/x-python","patch_set":5,"id":"7faddb67_03efa4b0","line":923,"updated":"2019-07-09 08:28:30.000000000","message":"We already have [1]\n\n[1] https://github.com/openstack/oslo.utils/blob/3ed4676f93996b9f1d81a2826020d0c8cead4425/oslo_utils/timeutils.py#L352","commit_id":"7fc7b68db5b508f8a83ba628da558599c79e7209"},{"author":{"_account_id":9531,"name":"liuyulong","display_name":"LIU Yulong","email":"i@liuyulong.me","username":"LIU-Yulong"},"change_message_id":"d5bd9963fc7aa1facac23adc123745bd6d37249c","unresolved":false,"context_lines":[{"line_number":920,"context_line":"        return (datetime.datetime.now() - self.start).total_seconds()"},{"line_number":921,"context_line":""},{"line_number":922,"context_line":""},{"line_number":923,"context_line":"def timecost(f):"},{"line_number":924,"context_line":""},{"line_number":925,"context_line":"    def wrapper(*args, **kwargs):"},{"line_number":926,"context_line":"        call_id \u003d uuidutils.generate_uuid()"}],"source_content_type":"text/x-python","patch_set":5,"id":"7faddb67_8b116aaf","line":923,"in_reply_to":"7faddb67_03efa4b0","updated":"2019-07-09 11:55:04.000000000","message":"Good to know that, but it can not distinguish each call for same RPC, so I will still add a wrapper here which call that function inside. And a log for the function start is needed as well. We need to know the precisely call start and end.\n\nSo after some much refactor, it is still worth to call that oslo.utils?","commit_id":"7fc7b68db5b508f8a83ba628da558599c79e7209"},{"author":{"_account_id":11975,"name":"Slawek Kaplonski","email":"skaplons@redhat.com","username":"slaweq"},"change_message_id":"157cc05c4831f563d944d4064ec33c7da0c28384","unresolved":false,"context_lines":[{"line_number":920,"context_line":"        return (datetime.datetime.now() - self.start).total_seconds()"},{"line_number":921,"context_line":""},{"line_number":922,"context_line":""},{"line_number":923,"context_line":"def timecost(f):"},{"line_number":924,"context_line":""},{"line_number":925,"context_line":"    def wrapper(*args, **kwargs):"},{"line_number":926,"context_line":"        call_id \u003d uuidutils.generate_uuid()"}],"source_content_type":"text/x-python","patch_set":5,"id":"7faddb67_15d6fbf2","line":923,"in_reply_to":"7faddb67_03efa4b0","updated":"2019-07-09 09:24:58.000000000","message":"ohh, I didn\u0027t know about it. So IMO this existing method can be used instead of introducing our own implementation for the same.","commit_id":"7fc7b68db5b508f8a83ba628da558599c79e7209"},{"author":{"_account_id":16688,"name":"Rodolfo Alonso","email":"ralonsoh@redhat.com","username":"rodolfo-alonso-hernandez"},"change_message_id":"80acf7e3aab4578a18d122f66fab6910ad5bf894","unresolved":false,"context_lines":[{"line_number":921,"context_line":"        return (datetime.datetime.now() - self.start).total_seconds()"},{"line_number":922,"context_line":""},{"line_number":923,"context_line":""},{"line_number":924,"context_line":"def timecost(call_id\u003duuidutils.generate_uuid()):"},{"line_number":925,"context_line":""},{"line_number":926,"context_line":"    def log_timecost(f):"},{"line_number":927,"context_line":"        message_base \u003d (\"Time-cost: call %(call_id)s function %(fname)s \") % {"}],"source_content_type":"text/x-python","patch_set":6,"id":"7faddb67_7a412f39","line":924,"updated":"2019-07-11 11:35:13.000000000","message":"Actually, you have here a double nesting. IMO, this is not needed. BTW, because of this, you need to \"call\" the decorator \"timecost\" as @timecost()\n\nAnyway, you can implement \"log_timecost\" as a single decorator, and assign call_id\u003duuidutils.generate_uuid() inside it.\n\n\n   def log_timecost(f):\n        call_id\u003duuidutils.generate_uuid()\n        message_base \u003d (\"Time-cost: call %(call_id)s function %(fname)s \") % {\n                        \"call_id\": call_id, \"fname\": f.__name__}\n        end_message \u003d (message_base + \"took %(seconds).3f seconds to run\")\n\n        @timeutils.time_it(LOG, message\u003dend_message, min_duration\u003dNone)\n        def wrapper(*args, **kwargs):\n            LOG.debug(message_base + \"start\")\n            ret \u003d f(*args, **kwargs)\n            return ret\n        return wrapper","commit_id":"0199f32428b43c0ba90b65db9035afd361e25445"},{"author":{"_account_id":9531,"name":"liuyulong","display_name":"LIU Yulong","email":"i@liuyulong.me","username":"LIU-Yulong"},"change_message_id":"4fc6d6b03f36ebc800df79be332efe436a63cec7","unresolved":false,"context_lines":[{"line_number":921,"context_line":"        return (datetime.datetime.now() - self.start).total_seconds()"},{"line_number":922,"context_line":""},{"line_number":923,"context_line":""},{"line_number":924,"context_line":"def timecost(call_id\u003duuidutils.generate_uuid()):"},{"line_number":925,"context_line":""},{"line_number":926,"context_line":"    def log_timecost(f):"},{"line_number":927,"context_line":"        message_base \u003d (\"Time-cost: call %(call_id)s function %(fname)s \") % {"}],"source_content_type":"text/x-python","patch_set":6,"id":"7faddb67_9aad0b33","line":924,"in_reply_to":"7faddb67_7a412f39","updated":"2019-07-11 12:28:47.000000000","message":"Yes, this is my backup version.","commit_id":"0199f32428b43c0ba90b65db9035afd361e25445"},{"author":{"_account_id":9531,"name":"liuyulong","display_name":"LIU Yulong","email":"i@liuyulong.me","username":"LIU-Yulong"},"change_message_id":"778022d566ebb96f9a5fc8086ec57e5cf6984220","unresolved":false,"context_lines":[{"line_number":925,"context_line":""},{"line_number":926,"context_line":"    def log_timecost(f):"},{"line_number":927,"context_line":"        message_base \u003d (\"Time-cost: call %(call_id)s function %(fname)s \") % {"},{"line_number":928,"context_line":"                        \"call_id\": call_id, \"fname\": f.__name__}"},{"line_number":929,"context_line":"        end_message \u003d (message_base + \"took %(seconds).3f seconds to run\")"},{"line_number":930,"context_line":""},{"line_number":931,"context_line":"        @timeutils.time_it(LOG, message\u003dend_message, min_duration\u003dNone)"}],"source_content_type":"text/x-python","patch_set":6,"id":"7faddb67_4755771c","line":928,"range":{"start_line":928,"start_character":35,"end_line":928,"end_character":42},"updated":"2019-07-11 14:23:42.000000000","message":"My original thought is to specify the call_id if someone want.","commit_id":"0199f32428b43c0ba90b65db9035afd361e25445"}]}