PHP 中使用 opentelemetry-auto-laravel 进行链路追踪时间片段不连续的问题

先上正菜

• PHP项目上了opentelemetry的时候发现有部分片段时间不连续

接入

• 安装扩展 (自动上报需要PHP8)
  • https://opentelemetry.io/docs/languages/php/automatic/
  • opentelemetry扩展
    • 容器中可以使用install-php-extensions opentelemetry安装
    • windows官方没有, 可以到这里下载ddl文件https://phpext.phptools.online/extension/php/opentelemetry-261
  • composer扩展
    • composer install open-telemetry/opentelemetry-auto-laravel

配置

TEL_PHP_AUTOLOAD_ENABLED=true
TEL_SERVICE_NAME=test
TEL_TRACES_EXPORTER=otlp
TEL_METRICS_EXPORTER=none
TEL_LOGS_EXPORTER=none
TEL_EXPORTER_OTLP_PROTOCOL=grpc
TEL_EXPORTER_OTLP_ENDPOINT=http://
TEL_EXPORTER_OTLP_HEADERS=Authentication=xxx
TEL_EXPORTER_OTLP_TIMEOUT=1000
TEL_EXPORTER_OTLP_TRACES_TIMEOUT=1000

运行

• open-telemetry/opentelemetry-auto-laravel这个项目通过composer.json的_register.php让Laravel自动加载https://github.com/open-telemetry/opentelemetry-php-contrib/blob/main/src/Instrumentation/Laravel/composer.json#L39

{
  "files": [
    "_register.php"
  ]
}

• 默认会收集request, cache,log,http client https://github.com/open-telemetry/opentelemetry-php-contrib/blob/main/src/Instrumentation/Laravel/src/LaravelInstrumentation.php
• 会根据以下解析出一个BatchProcessSpan
  • https://github.com/open-telemetry/opentelemetry-php/blob/main/src/SDK/Common/Configuration/Defaults.php#L115默认配置batch
  • https://github.com/open-telemetry/opentelemetry-php/blob/main/src/SDK/SdkAutoloader.php注册各种默认配置

public static function autoload(): bool
{
    if (!self::isEnabled() || self::isExcludedUrl()) {
        return false;
    }
    Globals::registerInitializer(function (Configurator $configurator) {
        $propagator = (new PropagatorFactory())->create();
        if (Sdk::isDisabled()) {
            //@see https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/configuration/sdk-environment-variables.md#general-sdk-configuration
            return $configurator->withPropagator($propagator);
        }
        $emitMetrics = Configuration::getBoolean(Variables::OTEL_PHP_INTERNAL_METRICS_ENABLED);

        $resource = ResourceInfoFactory::defaultResource();
        $exporter = (new ExporterFactory())->create();
        $meterProvider = (new MeterProviderFactory())->create($resource);
        // 主要关注这一行, 这里我们会创建出一个 BatchSpanProcessor 
        $spanProcessor = (new SpanProcessorFactory())->create($exporter, $emitMetrics ? $meterProvider : null);
        $tracerProvider = (new TracerProviderBuilder())
            ->addSpanProcessor($spanProcessor)
            ->setResource($resource)
            ->setSampler((new SamplerFactory())->create())
            ->build();

        $loggerProvider = (new LoggerProviderFactory())->create($emitMetrics ? $meterProvider : null, $resource);

        ShutdownHandler::register($tracerProvider->shutdown(...));
        ShutdownHandler::register($meterProvider->shutdown(...));
        ShutdownHandler::register($loggerProvider->shutdown(...));

        return $configurator
            ->withTracerProvider($tracerProvider)
            ->withMeterProvider($meterProvider)
            ->withLoggerProvider($loggerProvider)
            ->withPropagator($propagator)
        ;
    });

    return true;
}

案例代码

• 自定义一个类

<?php

namespace App\Service\Tracing;

use OpenTelemetry\API\Globals;
use OpenTelemetry\API\Trace\SpanInterface;
use OpenTelemetry\API\Trace\TracerInterface;

class Tracer
{
    protected TracerInterface $tracer;
    protected ?SpanInterface $lastSpan = null;
    protected ?SpanInterface $rootSpan = null;
    /**
     * @var array Span
     */
    protected array $spanMap = [];

    public function __construct()
    {
        $this->tracer = Globals::tracerProvider()
            ->getTracer('io.opentelemetry.contrib.php.laravel');
    }

    /**
     * 请查看 AppServiceProvider 注册为 scoped, 适用于 Octane
     * @return Tracer
     */
    public static function getInstance(): Tracer
    {
        return app(Tracer::class);
    }

    public function startRootSpan($name): void
    {
        $span = $this->startSpan($name);
        $this->rootSpan = $span;
    }

    public function startAndEndLastSpan($name): SpanInterface
    {
        $this->endLastSpan();
        return $this->startSpan($name);
    }

    public function startSpan($name): SpanInterface
    {
        $span = $this->tracer->spanBuilder($name)->startSpan();
        $this->spanMap[$name] = $span;
        $this->lastSpan = $span;
        return $span;
    }

    public function endRootSpan(): void
    {
        $this->endSpan($this->rootSpan);
    }

    /**
     * @return void 方便的 end 上一个 span
     */
    public function endLastSpan(): void
    {
        $this->endSpan($this->lastSpan);
    }

    public function endSpan(?SpanInterface $span): void
    {
        if (is_null($span)) {
            return;
        }

        $span->end();
    }
}

• 把Tracer类注册到服务提供者app/Providers/AppServiceProvider.php
  • 由于我们使用常驻内存运行https://github.com/laravel/octane
  • 服务提供者请使用scoped来注册

<?php

namespace App\Providers;

use App\Utils\Tracing\Tracer;
use Illuminate\Support\ServiceProvider;

class AppServiceProvider extends ServiceProvider
{
    /**
     * Register any application services.
     *
     * @return void
     */
    public function register()
    {
        // 整个生命周期只注册一次
        $this->app->scoped(Tracer::class, function () {
            return new Tracer();
        });
    }

    /**
     * Bootstrap any application services.
     *
     * @return void
     */
    public function boot()
    {
        //
    }
}

• 在控制器使用

<?php

namespace App\Http\Controllers;

use App\Service\Tracing;

class IndexAlbumsController extends Controller
{
    public function index()
    {
        $tracer = Tracer::getInstance();
        // 步骤 0
        $tracer->startRootSpan('xxxx');
        
        // 步骤 1
        $tracer->startSpan('s1');
        // 业务代码 xxx
        // 结束步骤 1, 并开启步骤 2
        $tracer->startAndEndLastSpan('s2');
        // 业务代码 xxx
        // 结束步骤 2
        $tracer->endLastSpan();
        
        // 结束 root
        $tracer->endRootSpan();
    }
}

问题

• 代码很简单, 就追踪几个函数, 看耗时, 不出意外的话, 意外还是发生了
• 线上偶尔会在$span->end()的时候耗时几百毫秒, 百思不得其解

查看end()的实现

• 实际上会走到BatchSpanProcessor类的onEnd方法

class BatchSpanProcessor {

    public function onEnd(ReadableSpanInterface $span): void
    {
        if ($this->closed) {
            return;
        }
        if (!$span->getContext()->isSampled()) {
            return;
        }

        if ($this->queueSize === $this->maxQueueSize) {
            $this->dropped++;

            return;
        }

        $this->queueSize++;
        $this->batch[] = $span->toSpanData();
        $this->nextScheduledRun ??= $this->clock->now() + $this->scheduledDelayNanos;

        if (count($this->batch) === $this->maxExportBatchSize) {
            $this->enqueueBatch();
        }
        if ($this->autoFlush) {
            // flush 
            $this->flush();
        }
    }
}

• 所以罪魁祸首flush方法, 这里会根据配置到达一定数量, 一定时间把链路追踪上报
• 由于PHP常规运行没有多线程, flush上报链路追踪的时候会阻塞当前进程

解决办法

1. flush 方法上多线程, 短期内不可能, 估计百分之九十九的项目都是没用多线程的
2. https://opentelemetry.io/docs/collector/使用Opentelemetry collector代理
3. 装作没看到!!!