Message242093
This was very exciting, I have never run gprof before; so just to make sure I did this correctly, I will list my steps:
1. compile with the -pg flag set
1. run the test with ./python -m timeit ...
1. $ gprof python gmon.out > profile.out
Here is default:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
22.48 0.87 0.87 PyEval_EvalFrameEx
9.82 1.25 0.38 PyObject_CallFunctionObjArgs
6.85 1.52 0.27 PyObject_GenericGetAttr
6.46 1.77 0.25 tupledealloc
5.56 1.98 0.22 PyArg_UnpackTuple
5.17 2.18 0.20 PyNumber_AsSsize_t
5.17 2.38 0.20 tuplesubscript
5.04 2.58 0.20 PyObject_Call
4.91 2.77 0.19 _PyType_Lookup
4.65 2.95 0.18 PyTuple_New
4.65 3.13 0.18 PyObject_GetItem
4.39 3.30 0.17 itemgetter_call
1.94 3.37 0.08 PyObject_GetAttr
1.81 3.44 0.07 PyObject_GC_UnTrack
1.81 3.51 0.07 _PyTuple_DebugMallocStats
1.03 3.55 0.04 PyErr_Occurred
1.03 3.59 0.04 property_descr_set
1.03 3.63 0.04 tuplerepr
0.78 3.66 0.03 PyLong_AsSsize_t
0.78 3.69 0.03 PyObject_GC_Track
0.52 3.71 0.02 property_descr_get
0.52 3.73 0.02 repeat_next
0.52 3.75 0.02 repeat_traverse
0.39 3.77 0.02 PyArg_ValidateKeywordArguments
0.39 3.78 0.02 _Py_CheckFunctionResult
0.26 3.79 0.01 PyCFunction_NewEx
0.26 3.80 0.01 PyCode_New
0.26 3.81 0.01 PyErr_Restore
0.26 3.82 0.01 PyType_GetSlot
0.26 3.83 0.01 _PyObject_CallMethodIdObjArgs
0.26 3.84 0.01 attrgetter_new
0.26 3.85 0.01 update_one_slot
0.13 3.86 0.01 _PyObject_GenericGetAttrWithDict
0.13 3.86 0.01 _PyObject_SetAttrId
0.13 3.87 0.01 gc_isenabled
0.13 3.87 0.01 visit_decref
Here is my patch:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
26.63 1.02 1.02 PyEval_EvalFrameEx
8.88 1.36 0.34 PyObject_GenericGetAttr
7.83 1.66 0.30 tupledealloc
6.27 1.90 0.24 PyObject_Call
5.74 2.12 0.22 PyTuple_New
5.48 2.33 0.21 property_descr_get
5.22 2.53 0.20 _PyType_Lookup
4.44 2.70 0.17 tuplesubscript
4.18 2.86 0.16 PyArg_UnpackTuple
3.92 3.01 0.15 PyNumber_AsSsize_t
3.66 3.15 0.14 PyObject_GetItem
2.87 3.26 0.11 itemgetter_call
2.61 3.36 0.10 PyObject_GC_UnTrack
1.70 3.43 0.07 PyObject_GetAttr
1.31 3.48 0.05 repeat_next
1.31 3.53 0.05 repeat_traverse
1.04 3.57 0.04 attrgetter_new
1.04 3.61 0.04 property_descr_set
0.78 3.64 0.03 PyErr_Occurred
0.78 3.67 0.03 PyErr_Restore
0.78 3.70 0.03 PyLong_AsSsize_t
0.78 3.73 0.03 PyType_GetSlot
0.52 3.75 0.02 PyObject_GC_Track
0.26 3.76 0.01 PyArg_ValidateKeywordArguments
0.26 3.77 0.01 PyDict_GetItem
0.26 3.78 0.01 _PyObject_GenericGetAttrWithDict
0.26 3.79 0.01 _PyTuple_DebugMallocStats
0.26 3.80 0.01 _Py_CheckFunctionResult
0.26 3.81 0.01 convertitem
0.26 3.82 0.01 r_object
0.26 3.83 0.01 tuplerepr
0.13 3.83 0.01 _PyObject_SetAttrId
It looks like you were correct that PyObject_CallFunctionObjArgs was eating up a lot of time. |
|
Date |
User |
Action |
Args |
2015-04-27 02:19:03 | llllllllll | set | recipients:
+ llllllllll, barry, rhettinger, eric.smith, eric.snow |
2015-04-27 02:19:03 | llllllllll | set | messageid: <1430101143.31.0.987074816843.issue23910@psf.upfronthosting.co.za> |
2015-04-27 02:19:03 | llllllllll | link | issue23910 messages |
2015-04-27 02:19:02 | llllllllll | create | |
|