Take the 2-minute tour ×
Programmers Stack Exchange is a question and answer site for professional programmers interested in conceptual questions about software development. It's 100% free, no registration required.

I am practicing algorithm and data structures. Therefore, I keep profiling my programs. Here is an example output from gprof:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ns/call  ns/call  name    
 29.76      2.58     2.58                             _IO_vfscanf_internal
 14.30      3.82     1.24                             ____strtof_l_internal
 11.71      4.84     1.02                             memcpy
  7.84      5.52     0.68  8400000    80.95    80.95  insertorupdate
  5.94      6.03     0.52                             _int_malloc
  5.77      6.53     0.50                             round_and_return
  3.81      6.86     0.33                             _IO_sputbackc
  3.23      7.14     0.28                             strlen
  2.88      7.39     0.25                             __strcmp_ia32
  2.13      7.58     0.19                             __isoc99_scanf
  2.13      7.76     0.19                             fgets
  2.02      7.94     0.18                             _IO_getline_info
  1.27      8.05     0.11                             __mpn_lshift
  1.21      8.15     0.11                             __memchr_sse2_bsf
  0.87      8.23     0.08                             malloc
  ... rest ...

But I found it hard to understand what this means. For example, my program takes a lot of time in standard functions, I guess it should be good, right? Because, if one of my functions were consuming most of the time, that could mean I was doing something wrong. But as I say, I am not sure if I am interpreting this correctly, so any suggesting or pointers reading this is welcome.

share|improve this question

3 Answers 3

up vote 4 down vote accepted

It's not good nor bad.

Imagine I tell you that I spend 45 minutes to travel from point A to point B. Is it fast? Is it slow? Does it mean I spend too much time? Or not? Until I say what is the point A, what is the point B, and what are my speed expectations, you can't tell anything.

Profiler results are similar. They don't tell you that something is absolutely bad or if your code is perfect performance-wise. They just show you raw results, letting you to interpret and study them.

You may have a valid case where one of your methods will spend a large amount of time doing something, because, well, it is expected to spend a large amount of time, since it has lots of work to do. Or maybe it's a sign that you must optimize this part of the code, because you expected this method to be at least one thousand times faster then it is actually.

Profiling helps by giving you some hints. SQL profilers, in this way, are maybe easy to understand:

  • If you see that when loading a web page, your web application sends the exact same query with the exact same parameters ten times, there is probably something wrong in your code, because you should do the query only once.

  • If you see that when loading a web page, a simple query takes 1.2 seconds, while you expected it to take a few milliseconds, there is a good sign that you or your colleagues forgot an index on a table or did something wrong with the query.

In the same way, code profilers:

  • Show that the same method is called again and again: sometimes, that's what you want. Sometimes, it may indicate a bug.

  • Show the time spent by a method. Depending on the case, either it's expected, or there is a bug.

This means that the purpose of a profiler is not to tell that your code is good or bad, - this is what requirements and acceptance testing is about -, but to identify the bottlenecks when you fail to met one of the non-functional requirements related to performance.

share|improve this answer

In this case, what it's telling you is that (as it's currently written) your program is spending most of its time doing I/O. The top two functions both appear to be involved with simply reading data from a file.

The part that would (or at least might) be somewhat disturbing is memcpy being the third highest, consuming almost 12% of the time. This may also be (a more or less unavoidable) part of reading input, but if you're using it directly, you might want to take a look where and how much you're using it to see whether you can leave data in the same place more, and (for example) rearrange pointers to it rather than moving blocks of data around (but keep in mind that even at best this is only going to improve speed by less than 12%).

As far as data structures and algorithms go, this is telling you they're (apparently) fast enough to contribute little to the overall run time. The major place to look is the I/O. From the looks of things, most of the time is being spent in a call to fscanf (or one of its cousins) doing a floating point conversion. If you were concerned with overall speed (not just the algorithms you wrote) an obvious possibility would be to look at storing that data in binary format to avoid converting from string to binary.

share|improve this answer

If you're working with algorithms and trying to show big-O behavior, it's better to count basic operations, like comparisons or memory allocations.

What you're seeing in your gprof output is your program spends most of its time reading input. And that's just unblocked CPU time. It doesn't count I/O time, even though you are still waiting for it. (And I/O is also CPU time, just with a different CPU.) If it counted I/O time as well, you would see an even larger fraction in that code.

gprof estimates how much time each routine held the program counter. It also counts how many times each routine was called from each other routine. From that it tries to figure out how much time each routine was responsible for in the sense of either spending time, or causing time to be spent. The way it calculates this is riddled with problems, as the original authors freely admitted, and it has basically stayed that way for 30 years. It is venerable, but it is not going to tell you much that you can depend on.

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.