0

I've been profiling a method using the stopwatch class, which is sub-millisecond accurate. The method runs thousands of times, on multiple threads.

I've discovered that most calls (90%+) take 0.1ms, which is acceptable. Occasionally, however, I find that the method takes several orders of magnitude longer, so that the average time for the call is actually more like 3-4ms.

What could be causing this?

The method itself is run from a delegate, and is essentially an event handler.

There are not many possible execution paths, and I've not yet discovered a path that would be conspicuously complicated.

I'm suspecting garbage collection, but I don't know how to detect whether it has occurred.

Finally, I am also considering whether the logging method itself is causing the problem. (The logger is basically a call to a static class + event listener that writes to the console.)

Improve this question
2
  • What is the method? There's no way to answer this without at least a general description of what it does. Commented Dec 16, 2009 at 16:07
  • The method is basically a collection searcher. Each call supplies an object, which is added to a big collection. The method returns one of the objects depending on various properties of the objects... Commented Dec 16, 2009 at 16:17

7 Answers 7

Reset to default
2

Just because Stopwatch has a high accuracy doesn't mean that other things can't get in the way - like the OS interrupting that thread to do something else. Garbage collection is another possibility. Writing to the console could easily cause delays like that.

Are you actually interested in individual call times, or is it overall performance which is important? It's generally more useful to run a method thousands of times and look at the total time - that's much more indicative of overall performance than individual calls which can be affected by any number of things on the computer.

Improve this answer
Sign up to request clarification or add additional context in comments.

2 Comments

I am actually interested in the call time. The slow executions are so much longer than the short ones that it makes a difference to performance. All this assumes of course that my timings are correct. But it gets hard to profile the thing when profiling itself interferes with execution.
@Carlos: But you should expect occasional interruptions from things like the GC. They will happen everywhere, unavoidably. If this is a method you're calling very frequently, you should almost certainly care far more about overall throughput than the occasional spike in time taken.
1

As I commented, you really should at least describe what your method does, if you're not willing to post some code (which would be best).

That said, one way you can tell if garbage collection has occurred (from Windows):

  1. Run perfmon (Start->Run->perfmon)
  2. Right-click on the graph; select "Add Counters..."
  3. Under "Performance object", select ".NET CLR Memory"
  4. From there you can select # Gen 0, 1, and 2 collections and click "Add"
  5. Now on the graph you will see a graph of all .NET CLR garbage collections
  6. Just keep this graph open while you run your application

EDIT: If you want to know if a collection occurred during a specific execution, why not do this?

int initialGen0Collections = GC.CollectionCount(0); int initialGen1Collections = GC.CollectionCount(1); int initialGen2Collections = GC.CollectionCount(2); // run your method if (GC.CollectionCount(0) > initialGen0Collections) // gen 0 collection occurred if (GC.CollectionCount(1) > initialGen1Collections) // gen 1 collection occurred if (GC.CollectionCount(2) > initialGen2Collections) // gen 2 collection occurred

SECOND EDIT: A couple of points on how to reduce garbage collections within your method:

  1. You mentioned in a comment that your method adds the object passed in to "a big collection." Depending on the type you use for said big collection, it may be possible to reduce garbage collections. For instance, if you use a List<T>, then there are two possibilities:

    a. If you know in advance how many objects you'll be processing, you should set the list's capacity upon construction:

    List<T> bigCollection = new List<T>(numObjects);

    b. If you don't know how many objects you'll be processing, consider using something like a LinkedList<T> instead of a List<T>. The reason for this is that a List<T> automatically resizes itself whenever a new item is added beyond its current capacity; this results in a leftover array that (eventually) will need to be garbage collected. A LinkedList<T> does not use an array internally (it uses LinkedListNode<T> objects), so it will not result in this garbage collection.

  2. If you are creating objects within your method (i.e., somewhere in your method you have one or more lines like Thing myThing = new Thing();), consider using a resource pool to eliminate the need for constantly constructing objects and thereby allocating more heap memory. If you need to know more about resource pooling, check out the Wikipedia article on Object Pools and the MSDN documentation on the ConcurrentBag<T> class, which includes a sample implementation of an ObjectPool<T>.

Improve this answer

2 Comments

I've actually got Perfmon open. The problem with this is that the method runs so fast that I can't tell if the GC happened during a given execution.
Hello, I've used this code in my function, and it explains the variation in execution time. For each generation of collection, the method takes progressively longer to execute, as one would expect. I'll now try to use a memory profiler to make sure the higher generation collections happen less often.
1

That can depend on many things and you really have to figure out which one you are delaing with.

  1. I'm not terribly familiar with what triggers garbage collection and what thread it runs on, but that sounds like a possibility.

  2. My first thought around this is with paging. If this is the first time the method runs and the application needs to page in some code to run the method, it would be waiting on that. Or, it could be the data that you're using within the method that triggered a cache miss and now you have to wait for that.

  3. Maybe you're doing an allocation and the allocator did some extra reshuffling in order to get you the allocation you requested.

  4. Not sure how thread time is calculated with Stopwatch, but a context switch might be what you're seeing.

  5. Or...it could be something completely different...

Basically, it could be one of several things and you really have to look at the code itself to see what is causing your occasional slow-down.

Improve this answer

3 Comments

Thanks. Now I'm suspecting a collection allocator. Perhaps I need to specify size in the constructors.
Try timing different parts of your method to see where the greatest difference is.
Based on your comments, I'd say you are likely seeing a realloc happening when your collection need to grow.
1

It could well be GC. If you use a profiler application such as Redgate's ANTS profiler you can profile % time in GC along side your application's performance to see what's going on.

In addition, you can use the CLRProfiler...

https://github.com/MicrosoftArchive/clrprofiler

Finally, Windows Performance Monitor will show the % time in GC for a given running applicaiton too.

These tools will help you get a holistic view of what's going on in your app as well as the OS in general.

I'm sure you know this stuff already but microbenchmarking such as this is sometimes useful for determining how fast one line of code might be compared to another than you might write, but you generally want to profile your application under typical load too.

Knowing that a given line of code is 10 times faster than another is useful, but if that line of code is easier to read and not part of a tight loop then the 10x performance hit might not be a problem.

Improve this answer

Comments

0

What you need is a performance profile to tell you exactly what causes a slow down. Here is a quick list And of course here is the ANTS profiler.

Without knowing what your operation is doing, it sounds like it could be the garbage collection. However that might not be the only reason. If you are reading or writing to the disc it is possible your application might have to wait while something else is using the disk.

Timing issues may occur if you have a multi-threaded application and another thread could be taking some processor time that is only running 10 % of the time. This is why a profiler would help.

Improve this answer

Comments

0

If you're only running the code "thousands" of times on a pretty quick function, the occasional longer time could easily be due to transient events on the system (maybe Windows decided it was time to cache something).

That being said, I would suggest the following:

  1. Run the function many many more times, and take an average.
  2. In the code that uses the function, determine if the function in question actually is a bottleneck. Use a profiler for this.
Improve this answer

1 Comment

I've run the function hundreds of thousands of times. The same sort of thing occurs. 0.110ms,0.105ms,0.189ms,25ms,6ms,0.2ms,0.090ms I've looked at both the averages and the individual stats. That's how I discovered the large variations.
0

It can be dependent on your OS, environment, page reads, CPU ticks per second and so on.

The most realistic way is to run an execution path several thousand times and take the average.

However, if that logging class is only called occasionally and it logs to disk, that is quite likely to be a slow-down factor if it has to seek on the drive first.

A read of http://en.wikipedia.org/wiki/Profiling_%28computer_programming%29 may give you an insight into more techniques for determining slowdowns in your applications, while a list of profiling tools that you may find useful is at:

http://en.wikipedia.org/wiki/Visual_Studio_Team_System_Profiler

specifically http://en.wikipedia.org/wiki/Visual_Studio_Team_System_Profiler if you're doing c# stuff.

Hope that helps!

Improve this answer

Comments

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.