Author llllllllll
Recipients barry, eric.smith, eric.snow, llllllllll, rhettinger
Date 2015-04-27.02:19:02
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1430101143.31.0.987074816843.issue23910@psf.upfronthosting.co.za>
In-reply-to
Content
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.
History
Date User Action Args
2015-04-27 02:19:03llllllllllsetrecipients: + llllllllll, barry, rhettinger, eric.smith, eric.snow
2015-04-27 02:19:03llllllllllsetmessageid: <1430101143.31.0.987074816843.issue23910@psf.upfronthosting.co.za>
2015-04-27 02:19:03lllllllllllinkissue23910 messages
2015-04-27 02:19:02llllllllllcreate