Issue29676
This issue tracker has been migrated to GitHub,
and is currently read-only.
For more information,
see the GitHub FAQs in the Python's Developer Guide.
Created on 2017-02-28 11:34 by xiang.zhang, last changed 2022-04-11 14:58 by admin. This issue is now closed.
Pull Requests | |||
---|---|---|---|
URL | Status | Linked | Edit |
PR 523 | merged | methane, 2017-03-06 17:16 |
Messages (6) | |||
---|---|---|---|
msg288707 - (view) | Author: Xiang Zhang (xiang.zhang) * ![]() |
Date: 2017-02-28 11:34 | |
Recently when I run the test suite test_cprofile always produces some verbose info but won't fail. This is not the case before. I am not sure this is a bug or not. git bisect tells me https://github.com/python/cpython/commit/5566bbb8d563646d83e8172410fa0c085e8233b1 is responsible. I also see the verbose info on some buildbots. [cpython]$ ./python -m test test_cprofile Run tests sequentially 0:00:00 [1/1] test_cprofile Stats.print_callers output for Profile doesn't fit expectation! --- +++ @@ -1,15 +1,16 @@ -profilee.py:110(__getattr__) <- 16 0.016 0.016 profilee.py:98(subhelper) -profilee.py:25(testfunc) <- 1 0.270 1.000 <string>:1(<module>) -profilee.py:35(factorial) <- 1 0.014 0.130 profilee.py:25(testfunc) - 20/3 0.130 0.147 profilee.py:35(factorial) - 2 0.006 0.040 profilee.py:84(helper2_indirect) -profilee.py:48(mul) <- 20 0.020 0.020 profilee.py:35(factorial) -profilee.py:55(helper) <- 2 0.040 0.600 profilee.py:25(testfunc) -profilee.py:73(helper1) <- 4 0.116 0.120 profilee.py:55(helper) -profilee.py:84(helper2_indirect) <- 2 0.000 0.140 profilee.py:55(helper) -profilee.py:88(helper2) <- 6 0.234 0.300 profilee.py:55(helper) - 2 0.078 0.100 profilee.py:84(helper2_indirect) -profilee.py:98(subhelper) <- 8 0.064 0.080 profilee.py:88(helper2) -{built-in method builtins.hasattr} <- 4 0.000 0.004 profilee.py:73(helper1) - 8 0.000 0.008 profilee.py:88(helper2) -{built-in method sys.exc_info} <- 4 0.000 0.000 profilee.py:73(helper1) +profilee.py:110(__getattr__) <- 16 0.016 0.016 profilee.py:98(subhelper) +profilee.py:25(testfunc) <- 1 0.270 1.000 <string>:1(<module>) +profilee.py:35(factorial) <- 1 0.014 0.130 profilee.py:25(testfunc) + 20/3 0.130 0.147 profilee.py:35(factorial) + 2 0.006 0.040 profilee.py:84(helper2_indirect) +profilee.py:48(mul) <- 20 0.020 0.020 profilee.py:35(factorial) +profilee.py:55(helper) <- 2 0.040 0.600 profilee.py:25(testfunc) +profilee.py:73(helper1) <- 4 0.116 0.120 profilee.py:55(helper) +profilee.py:84(helper2_indirect) <- 2 0.000 0.140 profilee.py:55(helper) +profilee.py:88(helper2) <- 6 0.234 0.300 profilee.py:55(helper) + 2 0.078 0.100 profilee.py:84(helper2_indirect) +profilee.py:98(subhelper) <- 8 0.064 0.080 profilee.py:88(helper2) +{built-in method builtins.hasattr} <- 4 0.000 0.004 profilee.py:73(helper1) + 8 0.000 0.008 profilee.py:88(helper2) +{built-in method sys.exc_info} <- 4 0.000 0.000 profilee.py:73(helper1) +{method 'append' of 'list' objects} <- 4 0.000 0.000 profilee.py:73(helper1) Stats.print_callees output for Profile doesn't fit expectation! --- +++ @@ -1,16 +1,16 @@ -<string>:1(<module>) -> 1 0.270 1.000 profilee.py:25(testfunc) -profilee.py:110(__getattr__) -> -profilee.py:25(testfunc) -> 1 0.014 0.130 profilee.py:35(factorial) - 2 0.040 0.600 profilee.py:55(helper) -profilee.py:35(factorial) -> 20/3 0.130 0.147 profilee.py:35(factorial) - 20 0.020 0.020 profilee.py:48(mul) -profilee.py:48(mul) -> -profilee.py:55(helper) -> 4 0.116 0.120 profilee.py:73(helper1) - 2 0.000 0.140 profilee.py:84(helper2_indirect) - 6 0.234 0.300 profilee.py:88(helper2) -profilee.py:73(helper1) -> 4 0.000 0.004 {built-in method builtins.hasattr} -profilee.py:84(helper2_indirect) -> 2 0.006 0.040 profilee.py:35(factorial) - 2 0.078 0.100 profilee.py:88(helper2) -profilee.py:88(helper2) -> 8 0.064 0.080 profilee.py:98(subhelper) -profilee.py:98(subhelper) -> 16 0.016 0.016 profilee.py:110(__getattr__) -{built-in method builtins.hasattr} -> 12 0.012 0.012 profilee.py:110(__getattr__) +<string>:1(<module>) -> 1 0.270 1.000 profilee.py:25(testfunc) +profilee.py:110(__getattr__) -> +profilee.py:25(testfunc) -> 1 0.014 0.130 profilee.py:35(factorial) + 2 0.040 0.600 profilee.py:55(helper) +profilee.py:35(factorial) -> 20/3 0.130 0.147 profilee.py:35(factorial) + 20 0.020 0.020 profilee.py:48(mul) +profilee.py:48(mul) -> +profilee.py:55(helper) -> 4 0.116 0.120 profilee.py:73(helper1) + 2 0.000 0.140 profilee.py:84(helper2_indirect) + 6 0.234 0.300 profilee.py:88(helper2) +profilee.py:73(helper1) -> 4 0.000 0.004 {built-in method builtins.hasattr} +profilee.py:84(helper2_indirect) -> 2 0.006 0.040 profilee.py:35(factorial) + 2 0.078 0.100 profilee.py:88(helper2) +profilee.py:88(helper2) -> 8 0.064 0.080 profilee.py:98(subhelper) +profilee.py:98(subhelper) -> 16 0.016 0.016 profilee.py:110(__getattr__) +{built-in method builtins.hasattr} -> 12 0.012 0.012 profilee.py:110(__getattr__) 1 test OK. Total duration: 73 ms Tests result: SUCCESS |
|||
msg288716 - (view) | Author: Inada Naoki (methane) * ![]() |
Date: 2017-02-28 13:48 | |
thanks. for summary, notable changes are: (print_callers) +{method 'append' of 'list' objects} <- 4 0.000 0.000 profilee.py:73(helper1) Stats.print_callees output for Profile doesn't fit expectation! and (print_callees) -profilee.py:73(helper1) -> 4 0.000 0.004 {built-in method builtins.hasattr} - 4 0.000 0.000 {built-in method sys.exc_info} +profilee.py:73(helper1) -> 4 0.000 0.004 {built-in method builtins.hasattr} |
|||
msg289121 - (view) | Author: Inada Naoki (methane) * ![]() |
Date: 2017-03-06 17:06 | |
OK, now I found what caused this difference. lsprof expect `func` is PyCFunction object. But it can be PyMethodDescrObject when LOAD_METHOD is used to call C method. In Modules/_lsprof.c (line 459): case PyTrace_C_CALL: if ((((ProfilerObject *)self)->flags & POF_BUILTINS) && PyCFunction_Check(arg)) { ptrace_enter_call(self, ((PyCFunctionObject *)arg)->m_ml, arg); } Document says just it's "Function object being called." https://docs.python.org/3.6/c-api/init.html#c.Py_tracefunc If "function object" means "any C object having tp_call", most easy way to solve this issue is adding PyMethodDescrObject support to lsprof. PyEval_GetFuncName() and PyEval_GetFuncDesc() should support it too. As a bonus, `list.append(L, x)` will be profiled like `L.append(x)`. It looks more consistent. On the other hand, if it means it's PyCFunction, we can't call PyMethodDescrObject directly. Since PyEval_SetProfile() is old function, I chose later way for now. |
|||
msg289619 - (view) | Author: STINNER Victor (vstinner) * ![]() |
Date: 2017-03-14 21:01 | |
Oh wow, I didn't expect this issue with tracing when the commit 5566bbb8d563646d83e8172410fa0c085e8233b1 was merged: test_sys_settrace and test_lsprof passed. Would it be possible to add an unit test? |
|||
msg289633 - (view) | Author: Xiang Zhang (xiang.zhang) * ![]() |
Date: 2017-03-15 02:49 | |
Actually the current test produces some noises, but it doesn't fail. |
|||
msg290280 - (view) | Author: Inada Naoki (methane) * ![]() |
Date: 2017-03-24 22:44 | |
New changeset 93fac8dd358cd0e85e7b59115db226ce685d3f6f by INADA Naoki in branch 'master': bpo-29676: fix lsprof can't profile C method call. (GH523) https://github.com/python/cpython/commit/93fac8dd358cd0e85e7b59115db226ce685d3f6f |
History | |||
---|---|---|---|
Date | User | Action | Args |
2022-04-11 14:58:43 | admin | set | github: 73862 |
2017-03-24 22:44:21 | methane | set | messages: + msg290280 |
2017-03-15 02:49:49 | xiang.zhang | set | messages: + msg289633 |
2017-03-14 21:01:38 | vstinner | set | nosy:
+ vstinner messages: + msg289619 |
2017-03-07 05:24:53 | methane | set | status: open -> closed resolution: fixed stage: resolved |
2017-03-06 17:18:33 | methane | set | components:
+ Interpreter Core, - Tests title: verbose output of test_cprofile -> C method is not profiled by lsprof |
2017-03-06 17:16:37 | methane | set | pull_requests: + pull_request431 |
2017-03-06 17:06:48 | methane | set | messages: + msg289121 |
2017-02-28 13:48:31 | methane | set | messages: + msg288716 |
2017-02-28 11:34:24 | xiang.zhang | create |