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?

Is it a one time issue or you can consistently reproduce it?

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?

Can you reproduce it with just 2 files where one includes another and nothing else?

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

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.

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.

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 :


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.

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.

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.

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

I'll do my best to dive into this.

Hi Dmitri, extra question regarding your example; you said that trivial function takes 0.1ms and you wrote:



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:


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