[issue29676] verbose output of test_cprofile

[INADA Naoki]

Changes by INADA Naoki :


--
pull_requests: +431

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue29676] verbose output of test_cprofile

[INADA Naoki]

INADA Naoki added the comment:

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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue29676] verbose output of test_cprofile

[INADA Naoki]

INADA Naoki added the comment:

thanks.
for summary, notable changes are:

(print_callers)
+{method 'append' of 'list' objects}   <-   40.0000.000 
 profilee.py:73(helper1)
Stats.print_callees output for Profile doesn't fit expectation!

and

(print_callees)
-profilee.py:73(helper1) ->   40.0000.004  {built-in 
method builtins.hasattr}
- 40.0000.000  {built-in 
method sys.exc_info}
+profilee.py:73(helper1)   ->   40.0000.004 
 {built-in method builtins.hasattr}

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue29676] verbose output of test_cprofile

[Xiang Zhang]

New submission from Xiang Zhang:

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__)<-  160.0160.016  
profilee.py:98(subhelper)
-profilee.py:25(testfunc)<-   10.2701.000  
:1()
-profilee.py:35(factorial)   <-   10.0140.130  
profilee.py:25(testfunc)
-  20/30.1300.147  
profilee.py:35(factorial)
- 20.0060.040  
profilee.py:84(helper2_indirect)
-profilee.py:48(mul) <-  200.0200.020  
profilee.py:35(factorial)
-profilee.py:55(helper)  <-   20.0400.600  
profilee.py:25(testfunc)
-profilee.py:73(helper1) <-   40.1160.120  
profilee.py:55(helper)
-profilee.py:84(helper2_indirect)<-   20.0000.140  
profilee.py:55(helper)
-profilee.py:88(helper2) <-   60.2340.300  
profilee.py:55(helper)
- 20.0780.100  
profilee.py:84(helper2_indirect)
-profilee.py:98(subhelper)   <-   80.0640.080  
profilee.py:88(helper2)
-{built-in method builtins.hasattr}  <-   40.0000.004  
profilee.py:73(helper1)
- 80.0000.008  
profilee.py:88(helper2)
-{built-in method sys.exc_info}  <-   40.0000.000  
profilee.py:73(helper1)
+profilee.py:110(__getattr__)  <-  160.0160.016 
 profilee.py:98(subhelper)
+profilee.py:25(testfunc)  <-   10.2701.000 
 :1()
+profilee.py:35(factorial) <-   10.0140.130 
 profilee.py:25(testfunc)
+20/30.1300.147 
 profilee.py:35(factorial)
+   20.0060.040 
 profilee.py:84(helper2_indirect)
+profilee.py:48(mul)   <-  200.0200.020 
 profilee.py:35(factorial)
+profilee.py:55(helper)<-   20.0400.600 
 profilee.py:25(testfunc)
+profilee.py:73(helper1)   <-   40.1160.120 
 profilee.py:55(helper)
+profilee.py:84(helper2_indirect)  <-   20.0000.140 
 profilee.py:55(helper)
+profilee.py:88(helper2)   <-   60.2340.300 
 profilee.py:55(helper)
+   20.0780.100 
 profilee.py:84(helper2_indirect)
+profilee.py:98(subhelper) <-   80.0640.080 
 profilee.py:88(helper2)
+{built-in method builtins.hasattr}<-   40.0000.004 
 profilee.py:73(helper1)
+   80.0000.008 
 profilee.py:88(helper2)
+{built-in method sys.exc_info}<-   40.0000.000 
 profilee.py:73(helper1)
+{method 'append' of 'list' objects}   <-   40.0000.000 
 profilee.py:73(helper1)
Stats.print_callees output for Profile doesn't fit expectation!
--- 

+++ 

@@ -1,16 +1,16 @@

-:1()->   10.2701.000  
profilee.py:25(testfunc)
-profilee.py:110(__getattr__)->
-profilee.py:25(testfunc)->   10.0140.130  
profilee.py:35(factorial)
- 20.0400.600  
profilee.py:55(helper)
-profilee.py:35(factorial)   ->20/30.1300.147  
profilee.py:35(factorial)
-200.0200.020  
profilee.py:48(mul)
-profilee.py:48(mul) ->
-profilee.py:55(helper)  ->   40.1160.120  
profilee.py:73(helper1)
- 20.0000.140  
profilee.py:84(helper2_indirect)
- 60.2340.300  
profilee.py:88(helper2)
-profilee.py:73(helper1) ->   40.0000.004  {built-in 
method builtins.hasattr}
-profilee.py:84(helper2_indirect)->   20.0060.040  
profilee.py:35(factorial)
- 20.0780.100  
profilee.py:88(helper2)
-profilee.py:88(helper2) ->   80.0640.080  
profilee.py:98(subhelper)
-profilee.py:98(subhelper)   ->  160.0160.016  
pro