NuSphere Forums Forum Index
NuSphere Forums
Reply to topic
Help to understand profiling results


Joined: 31 May 2017
Posts: 57
Reply with quote
Hello,
today I've ran the profiler on a project of mine and this is the first entry (with 92 Hits) under "Lines":

Summary
File: C:\Users\pc\Documents\websites\www\library\vendor\composer\ClassLoader.php
Line number: 450
Line time: 1,344 sec
Line time with children: 7,587 ms
Lines total: 3,052 sec
Page total: 1,703 sec

At line 450 I've this:

function includeFile($file)
{
include $file; // line 450
}

From this output I understand that the function includeFile($file) was called 92 times and that the instruction
include $file;
took 1,344 seconds to be executed. Moreover the code executed in these files took (only) 7,587ms. - is this correct?

Could you please tell me why the sum of the Time of all the lines (3,052 sec) is not the same of Page total? what is the difference?

To further dig in this profiling and understand what is the $file taking more time I've created this pseudo-manual-profiler:

/////////////////////

function includeFile($file)
{
if (!isset($GLOBALS['include_timings'])) {
$GLOBALS['include_timings'] = [];
$GLOBALS['tot_include_timings'] = 0;
}

$start = microtime(true);
include $file;
$sec = round(microtime(true)-$start,3);

$GLOBALS['include_timings'][] = "included '{$file}' in {$sec} sec.";
$GLOBALS['tot_include_timings'] += $sec;
}

function debug_include_timings() {
file_put_contents(_DOWNLOAD_DIR."/include_timings.txt", date("d/m/Y H:i:s")." - Total {$GLOBALS['tot_include_timings']} sec.\n".join($GLOBALS['include_timings'], "\n"));
}

register_shutdown_function('Composer\Autoload\debug_include_timings');

/////////////////////

I was expecting that tot_include_timings was more or less exactly 1,344 sec, but is much less; this is the output saved in the file:

01/04/2020 16:43:17 - Total 0.066 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\Autoloader.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Loader\LoaderInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Loader\ExistsLoaderInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Loader\SourceContextLoaderInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Loader\FilesystemLoader.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\Loader\Filesystem.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Environment.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\Environment.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Cache\CacheInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Cache\NullCache.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Extension\ExtensionInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Extension\AbstractExtension.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Extension\CoreExtension.php' in 0.003 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Extension\EscaperExtension.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Extension\OptimizerExtension.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Extension\StagingExtension.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TemplateWrapper.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Source.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\LexerInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Lexer.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\TokenParserBrokerInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\TokenParserBroker.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\NodeInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\CompilerInterface.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Compiler.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Node.php' in 0.004 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TwigFilter.php' in 0.005 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TwigFunction.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TwigTest.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Token.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\ParserInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Parser.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\TokenParserInterface.php' in 0.004 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\AbstractTokenParser.php' in 0.004 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\ApplyTokenParser.php' in 0.005 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\ForTokenParser.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\IfTokenParser.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\ExtendsTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\IncludeTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\BlockTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\UseTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\FilterTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\MacroTokenParser.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\ImportTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\FromTokenParser.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\SetTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\SpacelessTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\FlushTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\DoTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\EmbedTokenParser.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\WithTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\DeprecatedTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\ExpressionParser.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenParser\AutoEscapeTokenParser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\NodeVisitor\NodeVisitorInterface.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\NodeVisitor\AbstractNodeVisitor.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\NodeVisitor\EscaperNodeVisitor.php' in 0.002 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\NodeVisitor\SafeAnalysisNodeVisitor.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\NodeVisitor\OptimizerNodeVisitor.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\TokenStream.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\NodeOutputInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\TextNode.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\AbstractExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\NameExpression.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\PrintNode.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\AssignNameExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\ConstantExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Binary\AbstractBinary.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Binary\GreaterEqualBinary.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\IfNode.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\ArrayExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/lib\Twig\TemplateInterface.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Template.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\GetAttrExpression.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\ConditionalExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\CallExpression.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\FunctionExpression.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\ForNode.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\ForLoopNode.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\FilterExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Binary\GreaterBinary.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Binary\AddBinary.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Binary\EqualBinary.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\ArrowFunctionExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Unary\AbstractUnary.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Unary\NotUnary.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\ModuleNode.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\BodyNode.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\NodeTraverser.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\DoNode.php' in 0.001 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\InlinePrint.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Binary\InBinary.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\TestExpression.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Test\NullTest.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Binary\AndBinary.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Filter\DefaultFilter.php' in 0 sec.
included 'C:\Users\pc\Documents\websites\www\library\vendor\composer/../twig/twig/src\Node\Expression\Test\DefinedTest.php' in 0 sec.

Do you have any explanation on the reason the profile measured 1,344 sec while my manual profiling only 0,066?
View user's profileFind all posts by blacktekSend private message
Site Admin

Joined: 13 Jul 2003
Posts: 8334
Reply with quote
Is it a one time issue or you can consistently reproduce it?

_________________
The PHP IDE team
View user's profileFind all posts by dmitriSend private messageVisit poster's website


Joined: 31 May 2017
Posts: 57
Reply with quote
I can constantly reproduce it. Same strange results with 2 different destination servers with different applications.

Could you kindly answer the other questions in the first post too?
View user's profileFind all posts by blacktekSend private message
Site Admin

Joined: 13 Jul 2003
Posts: 8334
Reply with quote
Can you reproduce it with just 2 files where one includes another and nothing else?

_________________
The PHP IDE team
View user's profileFind all posts by dmitriSend private messageVisit poster's website


Joined: 31 May 2017
Posts: 57
Reply with quote
Hi,
I was not able to reproduce with 2 files, I'll try again in the afternoon.

In the meantime could you please tell me if I read properly the pasted figures above? I paste here again :


From this output I understand that the function includeFile($file) was called 92 times and that the instruction
include $file;
took 1,344 seconds to be executed. Moreover the code executed in these files took (only) 7,587ms. - is this correct?

Could you please tell me why the sum of the Time of all the lines (3,052 sec) is not the same of Page total? what is the difference?

Thank you
View user's profileFind all posts by blacktekSend private message
Site Admin

Joined: 13 Jul 2003
Posts: 8334
Reply with quote
If you can reproduce it with simple include, then it has nothing to do with simple include.
Try to reproduce it with class auto-loader.

_________________
The PHP IDE team
View user's profileFind all posts by dmitriSend private messageVisit poster's website


Joined: 31 May 2017
Posts: 57
Reply with quote
Hello,
today I was trying to do new tests to reproduce this issue, but I'm unable to reproduce anymore.

Could you please help understanding the metrics provided?

Summary
File: C:\Users\pc\Documents\websites\www\library\vendor\composer\ClassLoader.php
Line number: 450
Line time: 1,344 sec
Line time with children: 7,587 ms
Lines total: 3,052 sec
Page total: 1,703 sec

It's not perfectly clear what is the difference between Line time and line time with children. The second one should be (IMO) the time spent to execute the line, together with the nested functions called.

Moreover not clear to me what is Lines total and Page total. Lines Total seems to be the total time of all the functions shown, but how is it possible that is bigger than Page time (that should be the total time of the page)?

The % on the Chart bar is not clear too. How it's calculated?
I've now profiled a page and the top "Function" is:

Summary
File: <PHP Core>
Function: file_exists()
Function time: 43,64 ms
Function time with children: 43,64 ms
Functions total: 164,3 ms
Page total: 143,2 ms

For this function the bar chart shows 85.46% - but what are the numerator and denominator? I expected 43,64 and 164,3 (or 143,20) - but it's not.
View user's profileFind all posts by blacktekSend private message
Site Admin

Joined: 13 Jul 2003
Posts: 8334
Reply with quote
If you experienced a problem but you can't reproduce it any more, why would you need my explanation for that? All I can __guess__ about your case is that it's not just include. It is an include that may also load class(es) and this activity and yield unusual results.
With regular include and regular auto-load, profiler shows regular results. Irregularity might be caused by problems with configuration, settings, data, CPU spikes in other processes etc.

As of line time vs line time with children, it depends on what you're checking. Let's check the following trivial case: module calls function a(), that calls function b(), that calls sleep(1). We'll see function a() spent very small time in itself -- indeed it's time spent just for calling b(). Function b() will show small time too, because all it does it passing execution to sleep(). Latter is a child for b(), so the b() time with children will be b's own time + time spent in sleep. Same goes to a() which will show time spent in a() itself plus time spent in its children, and there is only b as a child. Current module where you declared b and a, would accumulate time spent in a and b. It does not include sleep() because sleep is running elsewhere, but module with children will of course include sleep time.
Assume that trivial function takes 0.1ms. The results would be :

Code:
Function name  | Time   | Time with chidlren |
---------------+--------+--------------------+
<module>       |  0.3ms |  1000.3ms          |
a              |  0.2ms |  1000.2ms          |
b              |  0.1ms |  1000.1ms          |
sleep          | 1000ms |  1000ms            |

Regarding lines, picture will be very similar. Only line where you have sleep() call will show 1000ms -- both the line time and line time with chidlren. All the other lines will show something around microseconds.
Perhaps, you'd expect lines with a and b function calls to show something around 1000ms in time with children columns. But no, it's won't, at least not in current version of debugger or before because time with children is calculated on the client side and there is just not enough info to do so properly per line.

_________________
The PHP IDE team
View user's profileFind all posts by dmitriSend private messageVisit poster's website


Joined: 31 May 2017
Posts: 57
Reply with quote
Hi Dmitri,
I'm able to reproduce it in Magento, but not in a smaller websites with few scripts.

Thank you very much for the explanations, they make much sense.

But I'm still unable to understand how is possible that time with children is smaller then time without children, like the pasted real example:
Line time: 1,344 sec
Line time with children: 7,587 ms

Could you please provide an example?

Thank you again. I'm using phped license since 2006 I think, but this is the first time I'm experiencing such results.
View user's profileFind all posts by blacktekSend private message
Site Admin

Joined: 13 Jul 2003
Posts: 8334
Reply with quote
Perhaps you're not interested in theoretical build-ups. If you need an explanation for this particular case and not lengthy list of possible root causes, try to find a way to reproduce it in a test project. If I reproduce the problem, I'll do my best to explain it.
It's not necessary to be small project, just a project without sensitive data. It can be virtual machine snapshot. Preferably VmWare -- it's our work horse. Oracle vm would be accepted too.

_________________
The PHP IDE team
View user's profileFind all posts by dmitriSend private messageVisit poster's website


Joined: 31 May 2017
Posts: 57
Reply with quote
I'm very interested in the theory behind this. If you've a list of possible causes I would be happy to read/study them so I've a better understanding of the tool I use.
In any case during this weekend I'll do other tests. But if you ki dly can give more possible root causes you help me building the case.

Unfortunately I cannot export the current environment with the custom Magento we've built Sad

I'll do my best to dive into this.
View user's profileFind all posts by blacktekSend private message


Joined: 31 May 2017
Posts: 57
Reply with quote
Hi Dmitri, extra question regarding your example; you said that trivial function takes 0.1ms and you wrote:

dmitri wrote:


Code:
Function name  | Time   | Time with chidlren |
---------------+--------+--------------------+
<module>       |  0.3ms |  1000.3ms          |
a              |  0.2ms |  1000.2ms          |
b              |  0.1ms |  1000.1ms          |
sleep          | 1000ms |  1000ms            |



I was expecting that Time for function a is the time to call the trivial function = 0.1ms (and not 0.2ms); all the rest is ok for me; so I would expect this:
Code:
Function name  | Time   | Time with chidlren |
---------------+--------+--------------------+
<module>       |  0.3ms |  1000.3ms          |
a              |  0.1ms |  1000.2ms          |
b              |  0.1ms |  1000.1ms          |
sleep          | 1000ms |  1000ms            |


Am I wrong?

If I'm wrong I don't understand why the Time for a is 0.2ms (twice the trivial function) and not 0.1

Extra question:
what is the difference between File time and Page total? it's the time spent by the PHP interpret to create the opcode from the source? (the time spent before starting the execution of the first line of code). It could be the extra time for garbage collection too after executing the last line of code.

Thank you again, I continue to try to recreate the issue at the beginning of the post
View user's profileFind all posts by blacktekSend private message
Help to understand profiling results
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum
All times are GMT - 5 Hours  
Page 1 of 2  

  
  
 Reply to topic