the Inclusive Wall Time of Current function bigger than all Child functions

[shengbinxu]

the Inclusive Wall Time of current function is : 30,321us
and the total Inclusive Wall Time of all children function is less than 15,000us,
why ? I think the two time should nearly equal.
and the code is :

 protected function getTableMetadata($name, $type, $refresh)
    {
        $cache = null;
        if ($this->db->enableSchemaCache && !in_array($name, $this->db->schemaCacheExclude, true)) {
            $schemaCache = is_string($this->db->schemaCache) ? Yii::$app->get($this->db->schemaCache, false) : $this->db->schemaCache;
            if ($schemaCache instanceof Cache) {
                $cache = $schemaCache;
            }
        }
        $rawName = $this->getRawTableName($name);
        if ($refresh || !isset($this->_tableMetadata[$rawName])) {
            $this->loadTableMetadataFromCache($cache, $rawName);
        }
        if (!array_key_exists($type, $this->_tableMetadata[$rawName])) {
            $this->_tableMetadata[$rawName][$type] = $this->{'loadTable' . ucfirst($type)}($rawName);
            $this->saveTableMetadataToCache($cache, $rawName);
        }

        return $this->_tableMetadata[$rawName][$type];
    }

thank you very much!

[michaelbutler]

@shengbinxu The reason for that is inclusive CPU time means time spent in PHP code performing operations -- think string manipulations and arithmetic. It does not include time taken by I/O operations or waiting on the database or network, for example. Inclusive Wall Time includes everything including the I/O operations.

See https://blackfire.io/docs/reference-guide/time for more info.

Also, in your screen shot, the Inclusive CPU seems to be 0 us always. You highlighted actually the Inclusive Wall Time column in red. Please note the column alignments are a little odd. That said, 0 us for Inclusive CPU seems impossible but if those methods are only I/O bound then it could be true.

[shengbinxu]

@michaelbutler thank you very much ! I understand what you said.

the Inclusive Wall Time of current function is : 30,321us
and the total Inclusive Wall Time of all children function is less than 15,000us,
why ? I think the two time should nearly equal.

but, I still do not understand why about this, where the difference of about 15,000us gone?

[Krinkle]

@michaelbutler It takes time to run the statements in a function.

• Initialise parameters and call stack.
• Create $cache variable, and create null value, assigned.
• Access db object, access enableSchemaCache member, cast to boolean and compare to true.
• Evaluate instanceof, isset().
• Interpolate strings.
• Etc.

Similar to how your getRawTableName function needs time to run, your getTableMetadata itself also needs time for its own code.

This is named "Self time" or "Self Wall Time", which is shown here as 17 milliseconds, which means that (30.3 ms - 17.6 ms = ) there should be about 12.7 ms in the child functions. This looks correct to me, as the numbers in that screenshot add up to 12.61 ms.

[shengbinxu]

@Krinkle Very good answer! thank you very much