Joe Jevnik added the comment: 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. ---------- _______________________________________ Python tracker <rep...@bugs.python.org> <http://bugs.python.org/issue23910> _______________________________________ _______________________________________________ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
