Callgraph and visualization generated with sampling can be inaccurate and misleading as described in the the description

[Jakhotiya]

Visualization of how many times a child function was called inside parent can be wildly in accurate.

Following profiles were taken for exact same request and payload. Only in the first screenshot sampling is 5ms and in the second screenshot sampling is disabled

In this screenshot UI shown that Magento\Catalog\Model\Product\Type\AbstractType::prepareForCartAdvanced was called multiple times by Magento\Quote\Model\Quote::addProduct. That's not true. From the source code below you can see only one call is made for prepareForCartAdvanced inside addProduct.

This confused me because following is the source code

 public function addProduct(
        \Magento\Catalog\Model\Product $product,
        $request = null,
        $processMode = \Magento\Catalog\Model\Product\Type\AbstractType::PROCESS_MODE_FULL
    ) {
        if ($request === null) {
            $request = 1;
        }
        if (is_numeric($request)) {
            $request = $this->objectFactory->create(['qty' => $request]);
        }
        if (!$request instanceof \Magento\Framework\DataObject) {
            throw new \Magento\Framework\Exception\LocalizedException(
                __('We found an invalid request for adding product to quote.')
            );
        }

        if (!$product->isSalable()) {
            throw new \Magento\Framework\Exception\LocalizedException(
                __('Product that you are trying to add is not available.')
            );
        }

        $cartCandidates = $product->getTypeInstance()->prepareForCartAdvanced($request, $product, $processMode);

        /**
         * Error message
         */
        if (is_string($cartCandidates) || $cartCandidates instanceof \Magento\Framework\Phrase) {
            return (string)$cartCandidates;
        }

        /**
         * If prepare process return one object
         */
        if (!is_array($cartCandidates)) {
            $cartCandidates = [$cartCandidates];
        }

        $parentItem = null;
        $errors = [];
        $item = null;
        $items = [];
        foreach ($cartCandidates as $candidate) {
            // Child items can be sticked together only within their parent
            $stickWithinParent = $candidate->getParentProductId() ? $parentItem : null;
            $candidate->setStickWithinParent($stickWithinParent);

            $item = $this->getItemByProduct($candidate);
            if (!$item) {
                $item = $this->itemProcessor->init($candidate, $request);
                $item->setQuote($this);
                $item->setOptions($candidate->getCustomOptions());
                $item->setProduct($candidate);
                // Add only item that is not in quote already
                $this->addItem($item);
            }
            $items[] = $item;

            /**
             * As parent item we should always use the item of first added product
             */
            if (!$parentItem) {
                $parentItem = $item;
            }
            if ($parentItem && $candidate->getParentProductId() && !$item->getParentItem()) {
                $item->setParentItem($parentItem);
            }

            $this->itemProcessor->prepare($item, $request, $candidate);

            // collect errors instead of throwing first one
            if ($item->getHasError()) {
                $this->deleteItem($item);
                foreach ($item->getMessage(false) as $message) {
                    if (!in_array($message, $errors)) {
                        // filter duplicate messages
                        $errors[] = $message;
                    }
                }
                break;
            }
        }
        if (!empty($errors)) {
            throw new \Magento\Framework\Exception\LocalizedException(__(implode("\n", $errors)));
        }

        $this->_eventManager->dispatch('sales_quote_product_add_after', ['items' => $items]);
        return $parentItem;
    }

At this point I suspected if sampling was causing this. Then I disabled sampling and visualization is correct. Each Magento\Quote\Model\Quote::addProduct calls Magento\Catalog\Model\Product\Type\AbstractType::prepareForCartAdvanced only once.

I've experience this a few times but I do not know how to reproduce it for bare minimum php script.

This seems to happen because sampling will always miss a few function calls. The test case we are talking is "What happens when parent functions are missed but child functions are recorded. "

This may or may not have solution but makes sense to document this behavior.

[NoiseByNorthwest]

Hi Abhishek,

The problem lies in the fact that several calls to addProduct() are merged together in your sampled profile. This is one of the unavoidable inaccuracies caused by sampling mode.

Here is what happens technically:

• on a given sample the stack is "foo() -> bar()"
• on the next sample the stack is "foo() -> baz()", in this case SPX will consider that the foo() call is still the same one as the previous sample, although it could be another one.

This one could be fixed but I'm not sure that it's worth it as the other inaccuracies cannot be fixed (e.g. missing function calls with their costs wrongly integrated either in parent or siblings...) and will still make the timeline view more or less accurate depending on sampling period.

In sampling mode you must in fact not trust the function call boundaries (and consequently the function call counts in the flap profile & flame graph), you must just roughly trust the overall time collected for a given function or stack.

By the way 5ms is a very huge sampling period, maybe you use it to have a small report ? If you want to reduce SPX's own overhead in order to improve measured timings accuracy, a sampling period of 20 to 100us is sufficient in most cases.

There is however one thing that could be fixed, the documentation. The effects of sampling mode on the report analysis side are not documented.