vendredi 18 août 2017

Understanding the basics behind a profiling report - Part 3: other profiling data

Hi!

Third and last part about the textual profiling report ! (here are the links to the part 1, giving general informations about the profiling, and to the part 2 about the statistical data and distribution of the execution time)

Part 3 - Other useful data about the profiling 


So, this is how the last part looks when I profiled 1 to: 1000000000 do: [ :i | Object new]. As you can see, there are 4 parts, each dedicated to a specific aspect of the VM.

**Memory**
old +2,007,520 bytes
free +0 bytes

**GCs**
full 0 totalling 0ms (0.000% elapsed time)
scavenges 544 totalling 79ms (5.607% elapsed time), avg 0.145ms
tenures 10,893 (avg 0 GCs/tenure)
root table 0 overflows

**Compiled Code Compactions**
0 totalling 0ms (0.000% elapsed time)

**Events**
Process switches 6 (4 per second)
ioProcessEvents calls 69 (49 per second)
Interrupt checks 1170 (830 per second)
Event checks 1170 (830 per second)
Stack overflows 0 (0 per second)
Stack page divorces 0 (0 per second)

The first two parts are also available in the report provided when profiling with MessageTally, and this and this post explain what they are about.
Let's have a quick look at each of these parts, especially the ones not appearing in the MessageTally report:

1 & 2. Memory and GC's


**Memory**
old +2,007,520 bytes
free +0 bytes

**GCs**
full 0 totalling 0ms (0.000% elapsed time)
scavenges 544 totalling 79ms (5.607% elapsed time), avg 0.145ms
tenures 10,893 (avg 0 GCs/tenure)
root table 0 overflows

I will not go into the details of these parts as these are already explained in the articles I am referring to at the beginning of this post.

3. Compiled Code Compactions


**Compiled Code Compactions**
0 totalling 0ms (0.000% elapsed time)

This deals with the number of compiled code compactions. As already told in the installation tutorial of the VMProfiler, this kind of compaction occurs when the Cog method zone is full. A high (and time consuming) number of compactions may show that you need to increase the Cog Method zone size.

4. Events


**Events**
Process switches 6 (4 per second)
ioProcessEvents calls 69 (49 per second)
Interrupt checks 1170 (830 per second)
Event checks 1170 (830 per second)
Stack overflows 0 (0 per second)
Stack page divorces 0 (0 per second)


This part lists the different kinds of events that could happen during the profiling. 
Process switches is self-explanatory. 
ioProcessEvents calls refers to the amount of calls of the ioProcessEvents function, explained here.
Interrupt checks counts the amount of interrupt checks (for instance, if cmd+. was pressed).
Event checks counts the amount of event checks (for instance, if a mouse button was clicked).
Stack overflows happen when no stack page is available.
Stack pages divorce can happen in various cases, but it can be linked with stack overflows (not always!). 

All of these counters could indicate that something is wrong, if their behaviour doesn't match the expected one. 

... OK, nice, but what should I do now ?


This profiler is a really nice tool, especially if you want to understand what's going on on the VM when you execute your code, or if you are contributing to the VM and wants to understand precisely the impacts of your modifications.

The example on which the article is based, while good enough to explain the content of a profiling report, doesn't show what to do when the profiling data are unusual. Indeed, nothing seems to go wrong in this example.
But what means "going wrong"? Typically, it is when you spot what could be uncommon figures regarding the expected behaviour of your code. For instance :
  • a lot of full GC's,
  • a lot of compiled code compactions,
  • a lot of stack overflows,
  • a lot of stack pages divorces,
  • ... or of course, an (unexpected) large amount of time spent in some function(s).
If your program is slow, there are hardly out-of-the-box solutions to make it faster. The solutions to find are usually completely dependent to your case, and I cannot provide generic solutions.

However, there are a few things that you can try if you run into one of these cases. Don't forget to save your work :)
  • If the problem is about an unusual amount of GC's, you can try the solutions described in this article (in the GC tuning part). 
  • About the compiled code compactions, you can try to set a bigger machine code zone, using a similar script (you'll have to restart your image afterwards)Smalltalk vm parameterAt: 47 put: (Smalltalk vm parameterAt: 46) * 2(Parameter 46 being the size of machine code zone, the 47 being the desired size of machine code zone)
  • In general, you can check the different parameters by browsing SmalltalkImage>>vmParameterAt:, but a lot of them are read-only. 

I hope you enjoyed these posts about the report! The next post should deal with the evolution of the granularity of the report.

Aucun commentaire:

Enregistrer un commentaire