CODEWITHSUNDEEP
c++visual-c++profiling
Moberg
Moberg

Reputation: 5509

Why is my Profiling Class extremely slow?

I have never done profiling. Yesterday I programmed a ProfilingTimer class with a static timetable (a map<std::string, long long>) for time storage.

The constructor stores the starting tick, and the destructor calulates the elapsed time and adds it to the map:

ProfilingTimer::ProfilingTimer(std::string name)
 : mLocalNameLength(name.length())
{
 sNestedName += name;
 sNestedName += " > ";

 mStartTick = Platform::GetTimerTicks();
}

ProfilingTimer::~ProfilingTimer()
{
 long long totalTicks = Platform::GetTimerTicks() - mStartTick;

 sTimetable[sNestedName] += totalTicks;

 sNestedName.erase(sNestedName.length() - mLocalNameLength - 3);
}

In every function (or {block}) that I want to profile i need to add:

ProfilingTimer _ProfilingTimer("identifier");

This Profiling work all fine when I build a release version from Visual C++ 2010 Professional. But when I build as Debug I get a huge fps drop (from 63 down to ~20).

These are the numbers I get when I print my timetable (Debug build):

Update() > Tower::Update > : 2551 ms (84100m%)
Update() > Tower::Update > Tower::Update1 > : 1313 ms (43284m%)
Update() > Tower::Update > Tower::Update1 > Tower::FindNewTarget > : 6 ms (204m%)
Update() > Tower::Update > Tower::Update1 > Tower::HasTargetInRange > : 5 ms (184m%)
Update() > Tower::Update > Tower::Update2 > : 659 ms (21756m%)
Update() > Tower::Update > Tower::Update2 > Tower::HasTargetInRange > : 5 ms (187m%)

Update1 and Update2 times the first and second half respectively of Update. Why doesnt they add up to 84,1 %?

Still this 84% is a huge number - in release build I get this output:

Update() > : 770 ms (1549m%)
Update() > Tower::Update > : 722 ms (1452m%)
Update() > Tower::Update > Tower::FindNewTarget > : 44 ms (89m%)
Update() > Tower::Update > Tower::HasTargetInRange > : 92 ms (187m%)

1,4% instead of 84,1%. That is a huge difference!

Anyone knows why?

EDIT: I guess release is much faster than Debug, but why is this profiling so time consuming? Is std::map the time hogger or am I doing something extremely wrong?

EDIT: Updated the code. The initiation wasn't needed, and now stores the length of mLocalName instead of the actual string.

Upvotes: 4

Views: 613

Answers (3)

Clark Gaebel
Clark Gaebel

Reputation: 17978

There are a couple performance issues with your code.

  1. You're needlessly constructing an std::string in your ProfilingTimer constructor. I would recommend using a const char* as your parameter and using a custom Twine/Rope structure to do your appends.
  2. Why does mLocalName even exist? Just refer to name directly.
  3. As has been previously mentioned, don't ever profile in debug mode. It is beyond useless.
  4. Maps are actually quite slow in practice. I suggest using a hashtable. Unfortunately, implementations are compiler specific. If you're using Microsoft's, I believe they have unordered_map available for your use.

  5. Instead of doing sTimetable[sNestedName] = 0;, use the iterator you already retrieved.

    Timetable::iterator loc = sTimetable.find(sNestedName);
if(loc == sTimetable.end())
    sTimetable[sNestedName] = 0;

Addendum: Visual Studio comes with a profiler last I checked. Why not just use that?

Upvotes: 2

sth
sth

Reputation: 229794

Using long strings as an index into a std::map is probably not the fastest way to do this. Long strings with common beginnings mean that each time you compare two of these strings, a lot of characters have to be looked at to see if the strings are equal or not. std::map is basically a binary tree and does O(log(n)) comparisons on each lookup/insert. Using shorter or numeric keys should speed up all the map operations.

Also, using std::unordered_map might (or might not) improve speed, depending on how many elements the map contains and what kind of keys are used.

In the profiling class, the constructor should take the name as a reference to avoid creating an unnecessary copy of that string:

ProfilingTimer::ProfilingTimer(const std::string &name)

Generally avoiding unnecessary copies is a good idea. For example, you maybe don't really need the mLocalName member and it could be enough to just store the string length instead.

The profiling functions are probably called very often, so small delays can add up over the run of the program.

Upvotes: 2

wheaties
wheaties

Reputation: 35980

Microsoft adds a lot of safety checking to their container libraries in debug mode. This is beneficial. You'd rather catch out of bounds exceptions and the like in functions such as vector::operator[] instead of deciphering memory corruptions (would still recommend calling vector::at.) However, there's also a ton of other things that go into inserting debugger hooks that impact your code and it's performance.

Upvotes: 2

Related Questions