[Q] Performance(RPS) is lower then expected. Why and what to do? #876

dorantor · 2021-12-21T12:43:27Z

dorantor
Dec 21, 2021

Context:

$ rr -v
rr version 2.6.6 (build time: 2021-12-15T10:32:57+0000, go1.17.4)

$ php -v
PHP 7.4.24 (cli) (built: Sep 23 2021 22:09:39) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
with Zend OPcache v7.4.24, Copyright (c), by Zend Technologies
with blackfire v1.72.0~linux-x64-non_zts74, https://blackfire.io, by Blackfire

Q: Why peak performance could be lower than expected?
Under average load response time is less then 20ms(nginx $request_time). Same values can be seen with Blackfire (3-10ms). Some network overhead and something for rr itself. 20-30 is fine. 230 workers and CPU load is 50% at max. Expected RPS 7500-11500(1000/responseTime_ms * workers). But peak RPS I can see in our VictoriaMetrics reported by rr - 5k-6k RPS. 2-4 times less then expected. Why could it be? Where to look?
I understand why response time is growing under load - it's starting to queue requests(btw, how to monitor size of this queue?). But I don't understand why peak performance so low(about the same as we had with fpm, but a lot of network requests removed with rr, thanks to local in-memory cache). And what to do in order to fix it.

rustatian · 2021-12-21T12:56:54Z

rustatian
Dec 21, 2021
Maintainer

Hey @dorantor. 98% of the performance is made by your worker (if we don't take into account OS, hardware, etc). You may read this tread -> #799 it may give your some assumptions.
To see the queue size, use the http plugin with the http_metrics middleware with the metrics plugin.

http:
  address: 127.0.0.1:15389
  middleware: [ "http_metrics" ]
  .....

metrics:

  metrics:
    # Server metrics address
    #
    # Required for the production. Default: 127.0.0.1:9091, for the metrics 127.0.0.1:9091/metrics
    address: 127.0.0.1:3001

Then use can use grafana/Prometheus/curl -> curl http://127.0.0.1:3001/metrics. rr_http_requests_queue metric will point you to the actual queue size.

230 workers and CPU load is 50% at max

That says nothing. Because your workers might be blocked by some IO operations and become slow to respond. So it's near impossible to say what's wrong with your environment (or might be nothing wrong).

Try to share your config, your env, worker, as many details as you can. Also, take into account, that just multiplying response time by the number of workers is not a formula at all -> https://www.davepacheco.net/blog/2019/performance-puzzler-the-slow-server/.
It works only on the constant latency, which is almost impossible to achieve.

0 replies

rustatian · 2021-12-21T13:28:33Z

rustatian
Dec 21, 2021
Maintainer

Also, try to use a smaller number of workers. Should be a good reason to use such a big number. Try to use 10, then 20, and go on. Check the queue size at the same time. If you see, that with the 10 workers the queue size is 0, there is no sense to increase the number of workers (under high load for sure). Also, 10 workers are approx. 25MB/sec of throughput (network), with a simple hello world payload, might be the bottleneck in some other place (disk io, net).

1 reply

dorantor Dec 21, 2021
Author

With 128 workers performance dropped to 3.5k RPS(vs 5.5k RPS with 230). So number of workers seems to be correct.

dorantor · 2021-12-21T13:43:35Z

dorantor
Dec 21, 2021
Author

Thx for rr_http_requests_queue!

Response time is quite consistent, so I made this rough assumption with some added extra.

That says nothing. Because your workers might be blocked by some IO operations and become slow to respond. So it's near impossible to say what's wrong with your environment (or might be nothing wrong).

You see, under 6k RPS response time is ~20ms. When there are more(than 6k) requests it is still ~20ms(according to blackfire). My understanding that it should be able to work with higher RPS. With rr lots of data moved from memc to local(array) storage, thus reducing network induced latency.
Will try to reduce amount of workers. We have quite capable server (64HT cores), so we set workers more than cores assuming that when some network operations will happen, another worker will be working.

rr config:

server:
  # optional, only for linux under sudo user
  user: "exampleuser"
  command:  "php -dopcache.enable=1 -dopcache.enable_cli=1 /home/exampleuser/example.com/current/rr2-worker.php"

http:
  address: 10.42.2.11:8080
  pool:
    num_workers: 230
    max_jobs:    20480

  middleware: http_metrics

rpc:
  # TCP address:port for listening.
  #
  # Default: "tcp://127.0.0.1:6001"
  listen: tcp://127.0.0.1:6001

metrics:
  # prometheus client address (path /metrics added automatically)
  address: 10.42.2.11:2112

logs:
  mode: production
  level: warn
  channels:
    http:
      level: warn
      output: /var/log/rr.log
    server:
      output: /var/log/rr.log

Worker:

<?php
/**
 * @var Goridge\RelayInterface $relay
 */

use Spiral\RoadRunner;
use Nyholm\Psr7;

ini_set('display_errors', 'stderr');

require_once __DIR__ . '/vendor/autoload.php';

$worker = RoadRunner\Worker::create();
$psrFactory = new Psr7\Factory\Psr17Factory();

$worker = new RoadRunner\Http\PSR7Worker($worker, $psrFactory, $psrFactory, $psrFactory);

$framework = new Project\Framework();
$framework->registerDebugHandlers();


// let's create a blackfire client
$config = new \Blackfire\ClientConfiguration();
$config->setClientId('....');
$config->setClientToken('....');

$blackfire = new \Blackfire\Client($config);

while ($req = $worker->waitRequest()) {
    try {
        $cookies = $req->getCookieParams();
        $probe = null;
        if (\array_key_exists('blackfire', $cookies) && '1' == $cookies['blackfire']) {
            // start blackfire probe
            try {
                $probe = $blackfire->createProbe();
            } catch (\Blackfire\Exception\ExceptionInterface $e) {
                // @see https://blackfire.io/docs/php/integrations/sdk#error-management
            }
        }
        // Send request to framework
        $frameworkResponse = $framework
            ->processHttpServerRequest($req)
        ;

        $resp = new Psr7\Response(
            $frameworkResponse->getStatusCode(),
            $frameworkResponse->getHeaders(),
            (string) $frameworkResponse->getBody()
        );

        $worker->respond($resp);

        if ($probe && \array_key_exists('blackfire', $cookies) && '1' == $cookies['blackfire']) {
            $profile = $blackfire->endProbe($probe);
        }
    } catch (\Throwable $e) {
        $worker->getWorker()->error((string) $e);
    }
}

0 replies

rustatian · 2021-12-21T13:59:13Z

rustatian
Dec 21, 2021
Maintainer

max_jobs is limiting your RPS. If you have ~7k RPS, to exhaust this limit you need a 3sec for a worker to get a restart signal.
After receiving the restart signal for any worker, RR stops releasing the workers (because the RR needs to make sure, that process is reallocated correctly) and restart this process. It will happen with every worker. So, if you send 1 request and get 20ms, this doesn't mean, that if you start bombarding the RR with thousands of requests, the latency remains the same. Also, don't forget the article, you may have freezes up to 100-200ms when RR restarting the workers (might be more).

0 replies

dorantor · 2021-12-21T14:07:19Z

dorantor
Dec 21, 2021
Author

Unexpected turn of events. My understanding is that max_jobs preventing workers to restart too often and making local caching more efficient. But limits are still required in case of memory leak.
What should I set for max_jobs if I want to make it more efficient? Currently with rr workers -c /etc/roadrunner/.rr.yaml I see that workers are restarted after ~10-15 minutes. Small sample:

$ rr workers -c /etc/roadrunner/.rr.yaml
Workers of [http]:
+---------+-----------+---------+---------+---------+--------------------+
|   PID   |  STATUS   |  EXECS  | MEMORY  |  CPU%   |      CREATED       |
+---------+-----------+---------+---------+---------+--------------------+
|   19977 | working   |  10,157 | 51 MB   |   10.46 | 8 minutes ago      |
|   19978 | working   |   9,966 | 52 MB   |   10.68 | 8 minutes ago      |
|   19979 | working   |   9,747 | 51 MB   |   10.50 | 8 minutes ago      |
....

9 replies

dorantor Dec 21, 2021
Author

Okay. Reallocation takes place after at least 10 minutes after I've (re)started rr. So before that moment reallocation is not part of response time equation. And, to my understanding, if I remove this limit it will not change anything(at least for first 10 minutes after restart). And pause for 200ms once in 10 minutes seems affordable. It just 10 requests with our timings.
I mean, I understand that worker restart/reallocate takes time, but it doesn't seems main limiting factor. Even if takes 1second it roughly adds 1*100/600 ~= 0.15% to average response time. Again, if I understand correctly.

rustatian Dec 21, 2021
Maintainer

200ms (might be more or less) for every reallocation. That means, that almost 1m spend on the reallocation.

dorantor Dec 21, 2021
Author

But reallocation is happening once per 20480 requests(in our configuration)? So this 1m is distributed between our 230 workers, correct? Thus, picture still the same. This 1m is happening once per ~10*230 minutes.

rustatian Dec 21, 2021
Maintainer

No, 20480 requests are the single worker limit. With 7k RPS you'll exhaust this limit in 3s for a single worker. But, the requests were distributed by all 230 workers, so, after ~11.5 minutes, the reallocation starts, because every single worker exhausted its limit at the time.

dorantor Dec 22, 2021
Author

Yes, you right, I should be more precise. Once per 20480 requests processed by each worker, ofc.

dorantor · 2021-12-21T14:30:48Z

dorantor
Dec 21, 2021
Author

Maybe I should rephrase my question: how can I profile rr? I have profiling of my app. I have profiling for response time in nginx. But I don't have profiling in two places:

between nginx->rr before request got to my app(see worker above)
between rr->nginx after response dispatched from app

My suggestion that problem is somewhere between app response and nginx. But not sure how can I profile it in order to find bottleneck.
To clarify :) I'm not going to blame rr :) Most probably answer is somewhere in system settings, but it seems rr is holding keys to answer(s).

6 replies

dorantor Dec 21, 2021
Author

Thx! It could take few days.

dorantor Dec 22, 2021
Author

Hi! Managed to get profiling data under load:

$ go tool pprof -top http://127.0.0.1:6061
File: rr
Type: cpu
Duration: 30.12s, Total samples = 40.44s (134.28%)
Showing nodes accounting for 28.23s, 69.81% of 40.44s total
Dropped 651 nodes (cum <= 0.20s)
      flat  flat%   sum%        cum   cum%
     4.59s 11.35% 11.35%      5.01s 12.39%  syscall.Syscall
     1.55s  3.83% 15.18%      1.55s  3.83%  runtime.futex
     1.42s  3.51% 18.69%      1.42s  3.51%  runtime.epollwait
     1.07s  2.65% 21.34%      6.78s 16.77%  runtime.mallocgc
        1s  2.47% 23.81%         1s  2.47%  runtime.nextFreeFast (inline)
     0.98s  2.42% 26.24%      0.98s  2.42%  runtime.(*randomEnum).next (inline)
     0.97s  2.40% 28.64%      0.97s  2.40%  runtime.memclrNoHeapPointers
     0.83s  2.05% 30.69%      1.26s  3.12%  sync.(*poolChain).popTail
     0.80s  1.98% 32.67%      1.06s  2.62%  runtime.step
     0.77s  1.90% 34.57%      0.82s  2.03%  runtime.heapBitsSetType
     0.73s  1.81% 36.37%      3.33s  8.23%  runtime.stealWork
     0.70s  1.73% 38.11%      0.70s  1.73%  runtime.memmove
     0.63s  1.56% 39.66%      0.63s  1.56%  runtime.epollctl
     0.52s  1.29% 40.95%      0.75s  1.85%  runtime.checkTimers
     0.48s  1.19% 42.14%      0.48s  1.19%  runtime.usleep
     0.42s  1.04% 43.18%      0.49s  1.21%  syscall.Syscall6
     0.39s  0.96% 44.14%      0.83s  2.05%  runtime.mapassign_faststr
     0.39s  0.96% 45.10%      0.52s  1.29%  runtime.mapiternext
     0.38s  0.94% 46.04%      1.18s  2.92%  runtime.pcvalue
     0.38s  0.94% 46.98%      0.68s  1.68%  runtime.scanobject
     0.35s  0.87% 47.85%      0.90s  2.23%  runtime.lock2
     0.34s  0.84% 48.69%      0.34s  0.84%  runtime.pMask.read (inline)
...

Truncated for .30s < flat

Can you please help me how to read it? To my naive eye it seems syscall.Syscall should be investigated first, but still unclear where to look. Can provide full profile, if it helps.

dorantor Dec 22, 2021
Author

With tree I can see this section that seems might need attention

----------------------------------------------------------+-------------
                                            19.69s   100% |   net/http.(*conn).serve
     0.15s  0.37% 56.44%     19.69s 48.51%                | github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP
                                             7.77s 39.46% |   github.com/spiral/roadrunner/v2/pool.(*StaticPool).Exec
                                             5.69s 28.90% |   github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write
                                             2.20s 11.17% |   github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields
                                             2.05s 10.41% |   github.com/json-iterator/go.(*sortKeysMapEncoder).Encode
                                             0.23s  1.17% |   runtime.newobject
                                             0.22s  1.12% |   runtime.mallocgc
                                             0.16s  0.81% |   sync.(*Pool).Get
                                             0.15s  0.76% |   sync.(*Pool).Put
                                             0.11s  0.56% |   runtime.growslice
                                             0.10s  0.51% |   github.com/json-iterator/go.(*htmlEscapedStringEncoder).Encode
                                             0.05s  0.25% |   runtime.(*itabTableType).find
                                             0.05s  0.25% |   runtime.mapassign_faststr
----------------------------------------------------------+-------------

But still, I have doubts that I'm reading it correctly.

rustatian Dec 22, 2021
Maintainer

I have all these profiles.
syscall - especially read and write used to send data via process file descriptors. In Go, this is a costly operation because of different calling conventions.

The second profile shows the main entry point Exec. That would be strange if, under high load, the main hot path had 1 percent of the CPU time.

dorantor Dec 22, 2021
Author

Found that callgraph can exported as DOT file. And viewer: https://dreampuf.github.io/GraphvizOnline/
Maybe you'll see some "abnormalities" that will give me a hint where to look at my server environment..

digraph "rr" {
node [style=filled fillcolor="#f8f8f8"]
subgraph cluster_L { "File: rr" [shape=box fontsize=16 label="File: rr\lType: cpu\lDuration: 30.11s, Total samples = 40.59s (134.82%)\lShowing nodes accounting for 22.80s, 56.17% of 40.59s total\lDropped 672 nodes (cum <= 0.20s)\lDropped 79 edges (freq <= 0.04s)\lShowing top 80 nodes out of 265\l" tooltip="rr"] }
N1 [label="net/http\n(*conn)\nserve\n0.10s (0.25%)\nof 29.26s (72.09%)" id="node1" fontsize=11 shape=box tooltip="net/http.(*conn).serve (29.26s)" color="#b21000" fillcolor="#edd7d5"]
N2 [label="github\ncom/spiral/roadrunner-plugins/v2/http/handler\n(*Handler)\nServeHTTP\n0.15s (0.37%)\nof 19.69s (48.51%)" id="node2" fontsize=11 shape=box tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP (19.69s)" color="#b22200" fillcolor="#eddad5"]
N3 [label="runtime\nmallocgc\n1.01s (2.49%)\nof 6.94s (17.10%)" id="node3" fontsize=16 shape=box tooltip="runtime.mallocgc (6.94s)" color="#b25819" fillcolor="#ede1d8"]
N4 [label="runtime\nsystemstack\n0.02s (0.049%)\nof 4.30s (10.59%)" id="node4" fontsize=10 shape=box tooltip="runtime.systemstack (4.30s)" color="#b28253" fillcolor="#ede6e0"]
N5 [label="github\ncom/spiral/roadrunner/v2/worker\n(*SyncWorkerImpl)\nexecPayload\n0.08s (0.2%)\nof 7.08s (17.44%)" id="node5" fontsize=11 shape=box tooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload (7.08s)" color="#b25616" fillcolor="#ede0d8"]
N6 [label="sync\n(*Pool)\nGet\n0.18s (0.44%)\nof 3.47s (8.55%)" id="node6" fontsize=12 shape=box tooltip="sync.(*Pool).Get (3.47s)" color="#b28e66" fillcolor="#ede8e3"]
N7 [label="github\ncom/spiral/roadrunner-plugins/v2/http/handler\n(*Handler)\nWrite\n0.06s (0.15%)\nof 5.69s (14.02%)" id="node7" fontsize=10 shape=box tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write (5.69s)" color="#b26d35" fillcolor="#ede3dc"]
N8 [label="runtime\nfindrunnable\n0.18s (0.44%)\nof 6.54s (16.11%)" id="node8" fontsize=12 shape=box tooltip="runtime.findrunnable (6.54s)" color="#b25f22" fillcolor="#ede2da"]
N9 [label="syscall\nSyscall\n4.44s (10.94%)\nof 4.78s (11.78%)" id="node9" fontsize=24 shape=box tooltip="syscall.Syscall (4.78s)" color="#b27b49" fillcolor="#ede5df"]
N10 [label="runtime\nmcall\n0 of 7.24s (17.84%)" id="node10" fontsize=8 shape=box tooltip="runtime.mcall (7.24s)" color="#b25313" fillcolor="#ede0d7"]
N11 [label="runtime\nnewobject\n0.07s (0.17%)\nof 1.69s (4.16%)" id="node11" fontsize=11 shape=box tooltip="runtime.newobject (1.69s)" color="#b2a48d" fillcolor="#edebe8"]
N12 [label="runtime\nfutex\n1.66s (4.09%)" id="node12" fontsize=18 shape=box tooltip="runtime.futex (1.66s)" color="#b2a48d" fillcolor="#edebe8"]
N13 [label="runtime\nmakeslice\n0.01s (0.025%)\nof 2.91s (7.17%)" id="node13" fontsize=9 shape=box tooltip="runtime.makeslice (2.91s)" color="#b29572" fillcolor="#ede9e4"]
N14 [label="runtime\nnewstack\n0.07s (0.17%)\nof 2.83s (6.97%)" id="node14" fontsize=11 shape=box tooltip="runtime.newstack (2.83s)" color="#b29674" fillcolor="#ede9e4"]
N15 [label="github\ncom/spiral/goridge/v3/internal\nReceiveFrame\n0.05s (0.12%)\nof 3.39s (8.35%)" id="node15" fontsize=10 shape=box tooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame (3.39s)" color="#b28f67" fillcolor="#ede8e3"]
N16 [label="runtime\ngentraceback\n0.34s (0.84%)\nof 2.41s (5.94%)" id="node16" fontsize=13 shape=box tooltip="runtime.gentraceback (2.41s)" color="#b29b7d" fillcolor="#edeae6"]
N17 [label="runtime\nstealWork\n0.78s (1.92%)\nof 2.92s (7.19%)" id="node17" fontsize=15 shape=box tooltip="runtime.stealWork (2.92s)" color="#b29572" fillcolor="#ede9e4"]
N18 [label="github\ncom/json-iterator/go\n(*sortKeysMapEncoder)\nEncode\n0.10s (0.25%)\nof 2.05s (5.05%)" id="node18" fontsize=11 shape=box tooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode (2.05s)" color="#b2a085" fillcolor="#edeae7"]
N19 [label="github\ncom/json-iterator/go\n(*mapDecoder)\nDecode\n0.05s (0.12%)\nof 2.46s (6.06%)" id="node19" fontsize=10 shape=box tooltip="github.com/json-iterator/go.(*mapDecoder).Decode (2.46s)" color="#b29b7c" fillcolor="#edeae5"]
N20 [label="runtime\nmemmove\n0.79s (1.95%)" id="node20" fontsize=15 shape=box tooltip="runtime.memmove (0.79s)" color="#b2ada1" fillcolor="#edecea"]
N21 [label="github\ncom/spiral/roadrunner-plugins/v2/http/middleware/prometheus\n(*Plugin)\nMiddleware\nfunc1\n0.01s (0.025%)\nof 20.75s (51.12%)" id="node21" fontsize=9 shape=box tooltip="github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 (20.75s)" color="#b22000" fillcolor="#edd9d5"]
N22 [label="bufio\n(*Writer)\nFlush\n0.01s (0.025%)\nof 2.22s (5.47%)" id="node22" fontsize=9 shape=box tooltip="bufio.(*Writer).Flush (2.22s)" color="#b29e81" fillcolor="#edeae6"]
N23 [label="internal/poll\nignoringEINTRIO\n0.02s (0.049%)\nof 3.76s (9.26%)" id="node23" fontsize=10 shape=box tooltip="internal/poll.ignoringEINTRIO (3.76s)" color="#b28a5f" fillcolor="#ede7e2"]
N24 [label="net/http\n(*Server)\nServe\n0 of 1.60s (3.94%)" id="node24" fontsize=8 shape=box tooltip="net/http.(*Server).Serve (1.60s)" color="#b2a58f" fillcolor="#edebe8"]
N25 [label="runtime\nmapassign_faststr\n0.46s (1.13%)\nof 0.90s (2.22%)" id="node25" fontsize=14 shape=box tooltip="runtime.mapassign_faststr (0.90s)" color="#b2ac9e" fillcolor="#edecea"]
N26 [label="runtime\n(*sweepLocked)\nsweep\n0.13s (0.32%)\nof 1.07s (2.64%)" id="node26" fontsize=11 shape=box tooltip="runtime.(*sweepLocked).sweep (1.07s)" color="#b2aa9a" fillcolor="#edecea"]
N27 [label="runtime\nmemclrNoHeapPointers\n0.95s (2.34%)" id="node27" fontsize=16 shape=box tooltip="runtime.memclrNoHeapPointers (0.95s)" color="#b2ab9d" fillcolor="#edecea"]
N28 [label="net/http\nreadRequest\n0.03s (0.074%)\nof 2.12s (5.22%)" id="node28" fontsize=10 shape=box tooltip="net/http.readRequest (2.12s)" color="#b29f83" fillcolor="#edeae6"]
N29 [label="net/http\n(*chunkWriter)\nWrite\n0.02s (0.049%)\nof 1.75s (4.31%)" id="node29" fontsize=10 shape=box tooltip="net/http.(*chunkWriter).Write (1.75s)" color="#b2a38c" fillcolor="#edebe8"]
N30 [label="net/http\n(*response)\nfinishRequest\n0.01s (0.025%)\nof 2.53s (6.23%)" id="node30" fontsize=9 shape=box tooltip="net/http.(*response).finishRequest (2.53s)" color="#b29a7a" fillcolor="#ede9e5"]
N31 [label="runtime\nlock\n0 of 1.04s (2.56%)" id="node31" fontsize=8 shape=box tooltip="runtime.lock (1.04s)" color="#b2aa9b" fillcolor="#edecea"]
N32 [label="runtime\n(*mheap)\nalloc\n0.01s (0.025%)\nof 1.60s (3.94%)" id="node32" fontsize=9 shape=box tooltip="runtime.(*mheap).alloc (1.60s)" color="#b2a58f" fillcolor="#edebe8"]
N33 [label="runtime\nepollwait\n1.42s (3.50%)" id="node33" fontsize=18 shape=box tooltip="runtime.epollwait (1.42s)" color="#b2a793" fillcolor="#edebe9"]
N34 [label="runtime\nschedule\n0.10s (0.25%)\nof 7.02s (17.29%)" id="node34" fontsize=11 shape=box tooltip="runtime.schedule (7.02s)" color="#b25718" fillcolor="#ede1d8"]
N35 [label="sync\n(*Pool)\nPut\n0.22s (0.54%)\nof 0.66s (1.63%)" id="node35" fontsize=12 shape=box tooltip="sync.(*Pool).Put (0.66s)" color="#b2aea3" fillcolor="#edeceb"]
N36 [label="bufio\n(*Writer)\nWrite\n0.02s (0.049%)\nof 1.22s (3.01%)" id="node36" fontsize=10 shape=box tooltip="bufio.(*Writer).Write (1.22s)" color="#b2a997" fillcolor="#edebe9"]
N37 [label="runtime\nstep\n0.78s (1.92%)\nof 1.04s (2.56%)" id="node37" fontsize=15 shape=box tooltip="runtime.step (1.04s)" color="#b2aa9b" fillcolor="#edecea"]
N38 [label="sync\n(*poolChain)\npopTail\n1.10s (2.71%)\nof 1.51s (3.72%)" id="node38" fontsize=16 shape=box tooltip="sync.(*poolChain).popTail (1.51s)" color="#b2a691" fillcolor="#edebe8"]
N39 [label="net/textproto\n(*Reader)\nReadMIMEHeader\n0.04s (0.099%)\nof 1.06s (2.61%)" id="node39" fontsize=10 shape=box tooltip="net/textproto.(*Reader).ReadMIMEHeader (1.06s)" color="#b2aa9b" fillcolor="#edecea"]
N40 [label="internal/poll\n(*FD)\nWrite\n0.01s (0.025%)\nof 2.18s (5.37%)" id="node40" fontsize=9 shape=box tooltip="internal/poll.(*FD).Write (2.18s)" color="#b29e82" fillcolor="#edeae6"]
N41 [label="net/http\n(*chunkWriter)\nwriteHeader\n0.11s (0.27%)\nof 1.28s (3.15%)" id="node41" fontsize=11 shape=box tooltip="net/http.(*chunkWriter).writeHeader (1.28s)" color="#b2a896" fillcolor="#edebe9"]
N42 [label="github\ncom/json-iterator/go\n(*Iterator)\nReadString\n0.22s (0.54%)\nof 1.06s (2.61%)" id="node42" fontsize=12 shape=box tooltip="github.com/json-iterator/go.(*Iterator).ReadString (1.06s)" color="#b2aa9b" fillcolor="#edecea"]
N43 [label="net/http\n(*conn)\nreadRequest\n0.03s (0.074%)\nof 2.66s (6.55%)" id="node43" fontsize=10 shape=box tooltip="net/http.(*conn).readRequest (2.66s)" color="#b29878" fillcolor="#ede9e5"]
N44 [label="runtime\npcvalue\n0.28s (0.69%)\nof 1.09s (2.69%)" id="node44" fontsize=13 shape=box tooltip="runtime.pcvalue (1.09s)" color="#b2aa9a" fillcolor="#edece9"]
N45 [label="runtime\nslicebytetostring\n0.07s (0.17%)\nof 0.80s (1.97%)" id="node45" fontsize=11 shape=box tooltip="runtime.slicebytetostring (0.80s)" color="#b2ada0" fillcolor="#edecea"]
N46 [label="runtime\ngrowslice\n0.08s (0.2%)\nof 0.71s (1.75%)" id="node46" fontsize=11 shape=box tooltip="runtime.growslice (0.71s)" color="#b2ada2" fillcolor="#edeceb"]
N47 [label="runtime\nnextFreeFast\n1.09s (2.69%)" id="node47" fontsize=16 shape=box tooltip="runtime.nextFreeFast (1.09s)" color="#b2aa9a" fillcolor="#edece9"]
N48 [label="github\ncom/spiral/roadrunner/v2/pool\n(*StaticPool)\nExec\n0.07s (0.17%)\nof 7.77s (19.14%)" id="node48" fontsize=11 shape=box tooltip="github.com/spiral/roadrunner/v2/pool.(*StaticPool).Exec (7.77s)" color="#b24a07" fillcolor="#eddfd6"]
N49 [label="net/http\nHeader\nwriteSubset\n0.08s (0.2%)\nof 0.80s (1.97%)" id="node49" fontsize=11 shape=box tooltip="net/http.Header.writeSubset (0.80s)" color="#b2ada0" fillcolor="#edecea"]
N50 [label="internal/poll\n(*FD)\nRead\n0.02s (0.049%)\nof 1.96s (4.83%)" id="node50" fontsize=10 shape=box tooltip="internal/poll.(*FD).Read (1.96s)" color="#b2a187" fillcolor="#edeae7"]
N51 [label="github\ncom/json-iterator/go\n(*frozenConfig)\nMarshal\n0.01s (0.025%)\nof 2.60s (6.41%)" id="node51" fontsize=9 shape=box tooltip="github.com/json-iterator/go.(*frozenConfig).Marshal (2.60s)" color="#b29979" fillcolor="#ede9e5"]
N52 [label="internal/poll\n(*FD)\ndestroy\n0.01s (0.025%)\nof 1.63s (4.02%)" id="node52" fontsize=9 shape=box tooltip="internal/poll.(*FD).destroy (1.63s)" color="#b2a48e" fillcolor="#edebe8"]
N53 [label="runtime\ncheckTimers\n0.44s (1.08%)\nof 0.70s (1.72%)" id="node53" fontsize=14 shape=box tooltip="runtime.checkTimers (0.70s)" color="#b2ada3" fillcolor="#edeceb"]
N54 [label="runtime\n(*mcentral)\ncacheSpan\n0.05s (0.12%)\nof 1.23s (3.03%)" id="node54" fontsize=10 shape=box tooltip="runtime.(*mcentral).cacheSpan (1.23s)" color="#b2a997" fillcolor="#edebe9"]
N55 [label="runtime\nlock2\n0.43s (1.06%)\nof 1.06s (2.61%)" id="node55" fontsize=13 shape=box tooltip="runtime.lock2 (1.06s)" color="#b2aa9b" fillcolor="#edecea"]
N56 [label="runtime\nmapaccess1_faststr\n0.30s (0.74%)\nof 0.42s (1.03%)" id="node56" fontsize=13 shape=box tooltip="runtime.mapaccess1_faststr (0.42s)" color="#b2b0a9" fillcolor="#edeceb"]
N57 [label="runtime\nmapiternext\n0.30s (0.74%)\nof 0.37s (0.91%)" id="node57" fontsize=13 shape=box tooltip="runtime.mapiternext (0.37s)" color="#b2b0aa" fillcolor="#edecec"]
N58 [label="runtime\nmapassign\n0.13s (0.32%)\nof 0.67s (1.65%)" id="node58" fontsize=11 shape=box tooltip="runtime.mapassign (0.67s)" color="#b2aea3" fillcolor="#edeceb"]
N59 [label="github\ncom/spiral/roadrunner-plugins/v2/http\n(*Plugin)\nserveHTTP\n0 of 1.60s (3.94%)" id="node59" fontsize=8 shape=box tooltip="github.com/spiral/roadrunner-plugins/v2/http.(*Plugin).serveHTTP (1.60s)" color="#b2a58f" fillcolor="#edebe8"]
N60 [label="runtime\nepollctl\n0.58s (1.43%)" id="node60" fontsize=14 shape=box tooltip="runtime.epollctl (0.58s)" color="#b2aea5" fillcolor="#edeceb"]
N61 [label="runtime\n(*mheap)\nalloc\nfunc1\n0 of 1.24s (3.05%)" id="node61" fontsize=8 shape=box tooltip="runtime.(*mheap).alloc.func1 (1.24s)" color="#b2a897" fillcolor="#edebe9"]
N62 [label="net\n(*conn)\nRead\n0.03s (0.074%)\nof 0.85s (2.09%)" id="node62" fontsize=10 shape=box tooltip="net.(*conn).Read (0.85s)" color="#b2ac9f" fillcolor="#edecea"]
N63 [label="runtime\nadjustframe\n0.31s (0.76%)\nof 1.07s (2.64%)" id="node63" fontsize=13 shape=box tooltip="runtime.adjustframe (1.07s)" color="#b2aa9a" fillcolor="#edecea"]
N64 [label="runtime\n(*randomEnum)\nnext\n0.72s (1.77%)" id="node64" fontsize=15 shape=box tooltip="runtime.(*randomEnum).next (0.72s)" color="#b2ada2" fillcolor="#edeceb"]
N65 [label="net/http\nHeader\nClone\n0.07s (0.17%)\nof 0.52s (1.28%)" id="node65" fontsize=11 shape=box tooltip="net/http.Header.Clone (0.52s)" color="#b2afa7" fillcolor="#edeceb"]
N66 [label="runtime\ngcDrain\n0.08s (0.2%)\nof 0.84s (2.07%)" id="node66" fontsize=11 shape=box tooltip="runtime.gcDrain (0.84s)" color="#b2aca0" fillcolor="#edecea"]
N67 [label="runtime\nscanobject\n0.28s (0.69%)\nof 0.54s (1.33%)" id="node67" fontsize=13 shape=box tooltip="runtime.scanobject (0.54s)" color="#b2afa6" fillcolor="#edeceb"]
N68 [label="runtime\nheapBitsSetType\n0.61s (1.50%)\nof 0.71s (1.75%)" id="node68" fontsize=14 shape=box tooltip="runtime.heapBitsSetType (0.71s)" color="#b2ada2" fillcolor="#edeceb"]
N69 [label="runtime\n(*mheap)\nfreeSpan\nfunc1\n0 of 0.72s (1.77%)" id="node69" fontsize=8 shape=box tooltip="runtime.(*mheap).freeSpan.func1 (0.72s)" color="#b2ada2" fillcolor="#edeceb"]
N70 [label="github\ncom/spiral/roadrunner-plugins/v2/logger\n(*ZapAdapter)\nfields\n0.05s (0.12%)\nof 2.20s (5.42%)" id="node70" fontsize=10 shape=box tooltip="github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields (2.20s)" color="#b29e82" fillcolor="#edeae6"]
N71 [label="net\n(*netFD)\naccept\n0 of 0.68s (1.68%)" id="node71" fontsize=8 shape=box tooltip="net.(*netFD).accept (0.68s)" color="#b2aea3" fillcolor="#edeceb"]
N72 [label="runtime\ngcBgMarkWorker\n0.01s (0.025%)\nof 1.11s (2.73%)" id="node72" fontsize=9 shape=box tooltip="runtime.gcBgMarkWorker (1.11s)" color="#b2aa9a" fillcolor="#edece9"]
N73 [label="net/http\n(*connReader)\nbackgroundRead\n0.03s (0.074%)\nof 0.57s (1.40%)" id="node73" fontsize=10 shape=box tooltip="net/http.(*connReader).backgroundRead (0.57s)" color="#b2afa5" fillcolor="#edeceb"]
N74 [label="runtime\ncasgstatus\n0.24s (0.59%)\nof 0.27s (0.67%)" id="node74" fontsize=12 shape=box tooltip="runtime.casgstatus (0.27s)" color="#b2b1ac" fillcolor="#edecec"]
N75 [label="net\n(*netFD)\nClose\n0.01s (0.025%)\nof 1.94s (4.78%)" id="node75" fontsize=9 shape=box tooltip="net.(*netFD).Close (1.94s)" color="#b2a187" fillcolor="#edeae7"]
N76 [label="runtime\ncopystack\n0 of 2.41s (5.94%)" id="node76" fontsize=8 shape=box tooltip="runtime.copystack (2.41s)" color="#b29b7d" fillcolor="#edeae6"]
N77 [label="runtime\nunlock\n0 of 0.45s (1.11%)" id="node77" fontsize=8 shape=box tooltip="runtime.unlock (0.45s)" color="#b2afa8" fillcolor="#edeceb"]
N78 [label="syscall\nSyscall6\n0.40s (0.99%)\nof 0.45s (1.11%)" id="node78" fontsize=13 shape=box tooltip="syscall.Syscall6 (0.45s)" color="#b2afa8" fillcolor="#edeceb"]
N79 [label="runtime\nsweepone\n0.10s (0.25%)\nof 0.67s (1.65%)" id="node79" fontsize=11 shape=box tooltip="runtime.sweepone (0.67s)" color="#b2aea3" fillcolor="#edeceb"]
N80 [label="runtime\n(*mcache)\nrefill\n0.08s (0.2%)\nof 1.60s (3.94%)" id="node80" fontsize=11 shape=box tooltip="runtime.(*mcache).refill (1.60s)" color="#b2a58f" fillcolor="#edebe8"]
N1 -> N21 [label=" 20.75s" weight=52 penwidth=3 color="#b22000" tooltip="net/http.(*conn).serve ... github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 (20.75s)" labeltooltip="net/http.(*conn).serve ... github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 (20.75s)" style="dotted"]
N21 -> N2 [label=" 19.69s" weight=49 penwidth=3 color="#b22200" tooltip="github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 ... github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP (19.69s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 ... github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP (19.69s)" style="dotted"]
N2 -> N48 [label=" 7.77s" weight=20 color="#b24a07" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP -> github.com/spiral/roadrunner/v2/pool.(*StaticPool).Exec (7.77s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP -> github.com/spiral/roadrunner/v2/pool.(*StaticPool).Exec (7.77s)"]
N48 -> N5 [label=" 7.08s" weight=18 color="#b25616" tooltip="github.com/spiral/roadrunner/v2/pool.(*StaticPool).Exec ... github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload (7.08s)" labeltooltip="github.com/spiral/roadrunner/v2/pool.(*StaticPool).Exec ... github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload (7.08s)" style="dotted"]
N10 -> N34 [label=" 7s" weight=18 color="#b25718" tooltip="runtime.mcall ... runtime.schedule (7s)" labeltooltip="runtime.mcall ... runtime.schedule (7s)" style="dotted"]
N34 -> N8 [label=" 6.54s" weight=17 color="#b25f22" tooltip="runtime.schedule -> runtime.findrunnable (6.54s)" labeltooltip="runtime.schedule -> runtime.findrunnable (6.54s)"]
N2 -> N7 [label=" 5.69s" weight=15 color="#b26d35" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP -> github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write (5.69s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP -> github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write (5.69s)"]
N23 -> N9 [label=" 3.71s" weight=10 color="#b28a60" tooltip="internal/poll.ignoringEINTRIO ... syscall.Syscall (3.71s)" labeltooltip="internal/poll.ignoringEINTRIO ... syscall.Syscall (3.71s)" style="dotted"]
N5 -> N15 [label=" 3.39s" weight=9 color="#b28f67" tooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... github.com/spiral/goridge/v3/internal.ReceiveFrame (3.39s)" labeltooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... github.com/spiral/goridge/v3/internal.ReceiveFrame (3.39s)" style="dotted"]
N8 -> N17 [label=" 2.92s" weight=8 color="#b29572" tooltip="runtime.findrunnable -> runtime.stealWork (2.92s)" labeltooltip="runtime.findrunnable -> runtime.stealWork (2.92s)"]
N13 -> N3 [label=" 2.90s" weight=8 color="#b29572" tooltip="runtime.makeslice -> runtime.mallocgc (2.90s)" labeltooltip="runtime.makeslice -> runtime.mallocgc (2.90s)"]
N1 -> N43 [label=" 2.66s" weight=7 color="#b29878" tooltip="net/http.(*conn).serve -> net/http.(*conn).readRequest (2.66s)" labeltooltip="net/http.(*conn).serve -> net/http.(*conn).readRequest (2.66s)"]
N2 -> N51 [label=" 2.60s" weight=7 color="#b29979" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... github.com/json-iterator/go.(*frozenConfig).Marshal (2.60s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... github.com/json-iterator/go.(*frozenConfig).Marshal (2.60s)" style="dotted"]
N1 -> N30 [label=" 2.53s" weight=7 color="#b29a7a" tooltip="net/http.(*conn).serve -> net/http.(*response).finishRequest (2.53s)" labeltooltip="net/http.(*conn).serve -> net/http.(*response).finishRequest (2.53s)"]
N7 -> N19 [label=" 2.46s" weight=7 color="#b29b7c" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... github.com/json-iterator/go.(*mapDecoder).Decode (2.46s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... github.com/json-iterator/go.(*mapDecoder).Decode (2.46s)" style="dotted"]
N14 -> N76 [label=" 2.41s" weight=6 color="#b29b7d" tooltip="runtime.newstack -> runtime.copystack (2.41s)" labeltooltip="runtime.newstack -> runtime.copystack (2.41s)"]
N2 -> N70 [label=" 2.20s" weight=6 color="#b29e82" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields (2.20s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields (2.20s)" style="dotted"]
N43 -> N28 [label=" 2.12s" weight=6 color="#b29f83" tooltip="net/http.(*conn).readRequest -> net/http.readRequest (2.12s)" labeltooltip="net/http.(*conn).readRequest -> net/http.readRequest (2.12s)"]
N40 -> N23 [label=" 2.08s\n (inline)" weight=6 color="#b29f84" tooltip="internal/poll.(*FD).Write -> internal/poll.ignoringEINTRIO (2.08s)" labeltooltip="internal/poll.(*FD).Write -> internal/poll.ignoringEINTRIO (2.08s)"]
N51 -> N18 [label=" 2.05s" weight=6 color="#b2a085" tooltip="github.com/json-iterator/go.(*frozenConfig).Marshal ... github.com/json-iterator/go.(*sortKeysMapEncoder).Encode (2.05s)" labeltooltip="github.com/json-iterator/go.(*frozenConfig).Marshal ... github.com/json-iterator/go.(*sortKeysMapEncoder).Encode (2.05s)" style="dotted"]
N76 -> N16 [label=" 2.02s" weight=5 color="#b2a086" tooltip="runtime.copystack -> runtime.gentraceback (2.02s)" labeltooltip="runtime.copystack -> runtime.gentraceback (2.02s)"]
N1 -> N75 [label=" 1.94s" weight=5 color="#b2a187" tooltip="net/http.(*conn).serve ... net.(*netFD).Close (1.94s)" labeltooltip="net/http.(*conn).serve ... net.(*netFD).Close (1.94s)" style="dotted"]
N70 -> N14 [label=" 1.78s" weight=5 color="#b2a38b" tooltip="github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields ... runtime.newstack (1.78s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields ... runtime.newstack (1.78s)" style="dotted"]
N50 -> N23 [label=" 1.68s\n (inline)" weight=5 color="#b2a48d" tooltip="internal/poll.(*FD).Read -> internal/poll.ignoringEINTRIO (1.68s)" labeltooltip="internal/poll.(*FD).Read -> internal/poll.ignoringEINTRIO (1.68s)"]
N75 -> N52 [label=" 1.63s" weight=5 color="#b2a48e" tooltip="net.(*netFD).Close ... internal/poll.(*FD).destroy (1.63s)" labeltooltip="net.(*netFD).Close ... internal/poll.(*FD).destroy (1.63s)" style="dotted"]
N11 -> N3 [label=" 1.62s" weight=4 color="#b2a48e" tooltip="runtime.newobject -> runtime.mallocgc (1.62s)" labeltooltip="runtime.newobject -> runtime.mallocgc (1.62s)"]
N59 -> N24 [label=" 1.60s" weight=4 color="#b2a58f" tooltip="github.com/spiral/roadrunner-plugins/v2/http.(*Plugin).serveHTTP -> net/http.(*Server).Serve (1.60s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http.(*Plugin).serveHTTP -> net/http.(*Server).Serve (1.60s)"]
N30 -> N22 [label=" 1.60s" weight=4 color="#b2a58f" tooltip="net/http.(*response).finishRequest -> bufio.(*Writer).Flush (1.60s)" labeltooltip="net/http.(*response).finishRequest -> bufio.(*Writer).Flush (1.60s)"]
N3 -> N80 [label=" 1.60s" weight=4 color="#b2a58f" tooltip="runtime.mallocgc ... runtime.(*mcache).refill (1.60s)" labeltooltip="runtime.mallocgc ... runtime.(*mcache).refill (1.60s)" style="dotted"]
N6 -> N38 [label=" 1.51s" weight=4 color="#b2a691" tooltip="sync.(*Pool).Get ... sync.(*poolChain).popTail (1.51s)" labeltooltip="sync.(*Pool).Get ... sync.(*poolChain).popTail (1.51s)" style="dotted"]
N22 -> N40 [label=" 1.45s" weight=4 color="#b2a692" tooltip="bufio.(*Writer).Flush ... internal/poll.(*FD).Write (1.45s)" labeltooltip="bufio.(*Writer).Flush ... internal/poll.(*FD).Write (1.45s)" style="dotted"]
N8 -> N33 [label=" 1.42s" weight=4 color="#b2a793" tooltip="runtime.findrunnable ... runtime.epollwait (1.42s)" labeltooltip="runtime.findrunnable ... runtime.epollwait (1.42s)" style="dotted"]
N6 -> N13 [label=" 1.30s" weight=4 color="#b2a895" tooltip="sync.(*Pool).Get ... runtime.makeslice (1.30s)" labeltooltip="sync.(*Pool).Get ... runtime.makeslice (1.30s)" style="dotted"]
N15 -> N50 [label=" 1.27s" weight=4 color="#b2a896" tooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... internal/poll.(*FD).Read (1.27s)" labeltooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... internal/poll.(*FD).Read (1.27s)" style="dotted"]
N32 -> N4 [label=" 1.24s" weight=4 color="#b2a897" tooltip="runtime.(*mheap).alloc -> runtime.systemstack (1.24s)" labeltooltip="runtime.(*mheap).alloc -> runtime.systemstack (1.24s)"]
N4 -> N61 [label=" 1.24s" weight=4 color="#b2a897" tooltip="runtime.systemstack -> runtime.(*mheap).alloc.func1 (1.24s)" labeltooltip="runtime.systemstack -> runtime.(*mheap).alloc.func1 (1.24s)"]
N80 -> N54 [label=" 1.23s" weight=4 color="#b2a997" tooltip="runtime.(*mcache).refill -> runtime.(*mcentral).cacheSpan (1.23s)" labeltooltip="runtime.(*mcache).refill -> runtime.(*mcentral).cacheSpan (1.23s)"]
N7 -> N36 [label=" 1.19s" weight=3 color="#b2a998" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... bufio.(*Writer).Write (1.19s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... bufio.(*Writer).Write (1.19s)" style="dotted"]
N15 -> N6 [label=" 1.16s" weight=3 color="#b2a998" tooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... sync.(*Pool).Get (1.16s)" labeltooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... sync.(*Pool).Get (1.16s)" style="dotted"]
N36 -> N29 [label=" 1.12s" weight=3 color="#b2aa99" tooltip="bufio.(*Writer).Write -> net/http.(*chunkWriter).Write (1.12s)" labeltooltip="bufio.(*Writer).Write -> net/http.(*chunkWriter).Write (1.12s)"]
N29 -> N41 [label=" 1.10s" weight=3 color="#b2aa9a" tooltip="net/http.(*chunkWriter).Write -> net/http.(*chunkWriter).writeHeader (1.10s)" labeltooltip="net/http.(*chunkWriter).Write -> net/http.(*chunkWriter).writeHeader (1.10s)"]
N3 -> N47 [label=" 1.09s\n (inline)" weight=3 color="#b2aa9a" tooltip="runtime.mallocgc -> runtime.nextFreeFast (1.09s)" labeltooltip="runtime.mallocgc -> runtime.nextFreeFast (1.09s)"]
N72 -> N4 [label=" 1.08s" weight=3 color="#b2aa9a" tooltip="runtime.gcBgMarkWorker ... runtime.systemstack (1.08s)" labeltooltip="runtime.gcBgMarkWorker ... runtime.systemstack (1.08s)" style="dotted"]
N52 -> N9 [label=" 1.07s" weight=3 color="#b2aa9a" tooltip="internal/poll.(*FD).destroy ... syscall.Syscall (1.07s)" labeltooltip="internal/poll.(*FD).destroy ... syscall.Syscall (1.07s)" style="dotted"]
N28 -> N39 [label=" 1.06s" weight=3 color="#b2aa9b" tooltip="net/http.readRequest -> net/textproto.(*Reader).ReadMIMEHeader (1.06s)" labeltooltip="net/http.readRequest -> net/textproto.(*Reader).ReadMIMEHeader (1.06s)"]
N16 -> N63 [label=" 1.05s" weight=3 color="#b2aa9b" tooltip="runtime.gentraceback -> runtime.adjustframe (1.05s)" labeltooltip="runtime.gentraceback -> runtime.adjustframe (1.05s)"]
N31 -> N55 [label=" 1.03s" weight=3 color="#b2aa9b" tooltip="runtime.lock ... runtime.lock2 (1.03s)" labeltooltip="runtime.lock ... runtime.lock2 (1.03s)" style="dotted"]
N19 -> N42 [label=" 0.95s" weight=3 color="#b2ab9d" tooltip="github.com/json-iterator/go.(*mapDecoder).Decode ... github.com/json-iterator/go.(*Iterator).ReadString (0.95s)" labeltooltip="github.com/json-iterator/go.(*mapDecoder).Decode ... github.com/json-iterator/go.(*Iterator).ReadString (0.95s)" style="dotted"]
N4 -> N66 [label=" 0.84s" weight=3 color="#b2aca0" tooltip="runtime.systemstack ... runtime.gcDrain (0.84s)" labeltooltip="runtime.systemstack ... runtime.gcDrain (0.84s)" style="dotted"]
N44 -> N37 [label=" 0.81s" weight=2 color="#b2aca0" tooltip="runtime.pcvalue -> runtime.step (0.81s)" labeltooltip="runtime.pcvalue -> runtime.step (0.81s)"]
N41 -> N49 [label=" 0.80s" weight=2 color="#b2ada0" tooltip="net/http.(*chunkWriter).writeHeader ... net/http.Header.writeSubset (0.80s)" labeltooltip="net/http.(*chunkWriter).writeHeader ... net/http.Header.writeSubset (0.80s)" style="dotted"]
N54 -> N32 [label=" 0.73s" weight=2 color="#b2ada2" tooltip="runtime.(*mcentral).cacheSpan ... runtime.(*mheap).alloc (0.73s)" labeltooltip="runtime.(*mcentral).cacheSpan ... runtime.(*mheap).alloc (0.73s)" style="dotted"]
N18 -> N14 [label=" 0.72s" weight=2 color="#b2ada2" tooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode -> runtime.newstack (0.72s)" labeltooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode -> runtime.newstack (0.72s)"]
N17 -> N64 [label=" 0.72s" weight=2 color="#b2ada2" tooltip="runtime.stealWork -> runtime.(*randomEnum).next (0.72s)" labeltooltip="runtime.stealWork -> runtime.(*randomEnum).next (0.72s)"]
N3 -> N68 [label=" 0.71s" weight=2 color="#b2ada2" tooltip="runtime.mallocgc -> runtime.heapBitsSetType (0.71s)" labeltooltip="runtime.mallocgc -> runtime.heapBitsSetType (0.71s)"]
N62 -> N50 [label=" 0.69s" weight=2 color="#b2aea3" tooltip="net.(*conn).Read ... internal/poll.(*FD).Read (0.69s)" labeltooltip="net.(*conn).Read ... internal/poll.(*FD).Read (0.69s)" style="dotted"]
N24 -> N71 [label=" 0.68s" weight=2 color="#b2aea3" tooltip="net/http.(*Server).Serve ... net.(*netFD).accept (0.68s)" labeltooltip="net/http.(*Server).Serve ... net.(*netFD).accept (0.68s)" style="dotted"]
N5 -> N13 [label=" 0.67s" weight=2 color="#b2aea3" tooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... runtime.makeslice (0.67s)" labeltooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... runtime.makeslice (0.67s)" style="dotted"]
N45 -> N3 [label=" 0.66s" weight=2 color="#b2aea3" tooltip="runtime.slicebytetostring -> runtime.mallocgc (0.66s)" labeltooltip="runtime.slicebytetostring -> runtime.mallocgc (0.66s)"]
N22 -> N29 [label=" 0.63s" weight=2 color="#b2aea4" tooltip="bufio.(*Writer).Flush -> net/http.(*chunkWriter).Write (0.63s)" labeltooltip="bufio.(*Writer).Flush -> net/http.(*chunkWriter).Write (0.63s)"]
N5 -> N40 [label=" 0.63s" weight=2 color="#b2aea4" tooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... internal/poll.(*FD).Write (0.63s)" labeltooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... internal/poll.(*FD).Write (0.63s)" style="dotted"]
N29 -> N36 [label=" 0.63s" weight=2 color="#b2aea4" tooltip="net/http.(*chunkWriter).Write -> bufio.(*Writer).Write (0.63s)" labeltooltip="net/http.(*chunkWriter).Write -> bufio.(*Writer).Write (0.63s)"]
N36 -> N22 [label=" 0.62s" weight=2 color="#b2aea4" tooltip="bufio.(*Writer).Write -> bufio.(*Writer).Flush (0.62s)" labeltooltip="bufio.(*Writer).Write -> bufio.(*Writer).Flush (0.62s)"]
N19 -> N58 [label=" 0.61s" weight=2 color="#b2aea5" tooltip="github.com/json-iterator/go.(*mapDecoder).Decode ... runtime.mapassign (0.61s)" labeltooltip="github.com/json-iterator/go.(*mapDecoder).Decode ... runtime.mapassign (0.61s)" style="dotted"]
N7 -> N65 [label=" 0.52s" weight=2 color="#b2afa7" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... net/http.Header.Clone (0.52s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... net/http.Header.Clone (0.52s)" style="dotted"]
N61 -> N26 [label=" 0.52s" weight=2 color="#b2afa7" tooltip="runtime.(*mheap).alloc.func1 ... runtime.(*sweepLocked).sweep (0.52s)" labeltooltip="runtime.(*mheap).alloc.func1 ... runtime.(*sweepLocked).sweep (0.52s)" style="dotted"]
N46 -> N3 [label=" 0.52s" weight=2 color="#b2afa7" tooltip="runtime.growslice -> runtime.mallocgc (0.52s)" labeltooltip="runtime.growslice -> runtime.mallocgc (0.52s)"]
N17 -> N53 [label=" 0.52s" weight=2 color="#b2afa7" tooltip="runtime.stealWork -> runtime.checkTimers (0.52s)" labeltooltip="runtime.stealWork -> runtime.checkTimers (0.52s)"]
N26 -> N69 [label=" 0.51s" weight=2 color="#b2afa7" tooltip="runtime.(*sweepLocked).sweep ... runtime.(*mheap).freeSpan.func1 (0.51s)" labeltooltip="runtime.(*sweepLocked).sweep ... runtime.(*mheap).freeSpan.func1 (0.51s)" style="dotted"]
N19 -> N3 [label=" 0.50s" weight=2 color="#b2afa7" tooltip="github.com/json-iterator/go.(*mapDecoder).Decode ... runtime.mallocgc (0.50s)" labeltooltip="github.com/json-iterator/go.(*mapDecoder).Decode ... runtime.mallocgc (0.50s)" style="dotted"]
N63 -> N44 [label=" 0.49s" weight=2 color="#b2afa7" tooltip="runtime.adjustframe ... runtime.pcvalue (0.49s)" labeltooltip="runtime.adjustframe ... runtime.pcvalue (0.49s)" style="dotted"]
N15 -> N13 [label=" 0.48s" weight=2 color="#b2afa7" tooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... runtime.makeslice (0.48s)" labeltooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... runtime.makeslice (0.48s)" style="dotted"]
N7 -> N25 [label=" 0.46s" weight=2 color="#b2afa8" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... runtime.mapassign_faststr (0.46s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... runtime.mapassign_faststr (0.46s)" style="dotted"]
N52 -> N60 [label=" 0.46s" weight=2 color="#b2afa8" tooltip="internal/poll.(*FD).destroy ... runtime.epollctl (0.46s)" labeltooltip="internal/poll.(*FD).destroy ... runtime.epollctl (0.46s)" style="dotted"]
N3 -> N27 [label=" 0.46s" weight=2 color="#b2afa8" tooltip="runtime.mallocgc ... runtime.memclrNoHeapPointers (0.46s)" labeltooltip="runtime.mallocgc ... runtime.memclrNoHeapPointers (0.46s)" style="dotted"]
N28 -> N62 [label=" 0.44s" weight=2 color="#b2b0a8" tooltip="net/http.readRequest ... net.(*conn).Read (0.44s)" labeltooltip="net/http.readRequest ... net.(*conn).Read (0.44s)" style="dotted"]
N42 -> N45 [label=" 0.41s" weight=2 color="#b2b0a9" tooltip="github.com/json-iterator/go.(*Iterator).ReadString ... runtime.slicebytetostring (0.41s)" labeltooltip="github.com/json-iterator/go.(*Iterator).ReadString ... runtime.slicebytetostring (0.41s)" style="dotted"]
N73 -> N62 [label=" 0.41s" weight=2 color="#b2b0a9" tooltip="net/http.(*connReader).backgroundRead -> net.(*conn).Read (0.41s)" labeltooltip="net/http.(*connReader).backgroundRead -> net.(*conn).Read (0.41s)"]
N69 -> N31 [label=" 0.36s\n (inline)" color="#b2b0aa" tooltip="runtime.(*mheap).freeSpan.func1 -> runtime.lock (0.36s)" labeltooltip="runtime.(*mheap).freeSpan.func1 -> runtime.lock (0.36s)"]
N79 -> N26 [label=" 0.36s" color="#b2b0aa" tooltip="runtime.sweepone -> runtime.(*sweepLocked).sweep (0.36s)" labeltooltip="runtime.sweepone -> runtime.(*sweepLocked).sweep (0.36s)"]
N32 -> N27 [label=" 0.35s" color="#b2b0aa" tooltip="runtime.(*mheap).alloc -> runtime.memclrNoHeapPointers (0.35s)" labeltooltip="runtime.(*mheap).alloc -> runtime.memclrNoHeapPointers (0.35s)"]
N66 -> N67 [label=" 0.35s" color="#b2b0aa" tooltip="runtime.gcDrain ... runtime.scanobject (0.35s)" labeltooltip="runtime.gcDrain ... runtime.scanobject (0.35s)" style="dotted"]
N55 -> N12 [label=" 0.34s" color="#b2b0ab" tooltip="runtime.lock2 ... runtime.futex (0.34s)" labeltooltip="runtime.lock2 ... runtime.futex (0.34s)" style="dotted"]
N5 -> N35 [label=" 0.28s" color="#b2b1ac" tooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... sync.(*Pool).Put (0.28s)" labeltooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... sync.(*Pool).Put (0.28s)" style="dotted"]
N1 -> N14 [label=" 0.27s" color="#b2b1ac" tooltip="net/http.(*conn).serve -> runtime.newstack (0.27s)" labeltooltip="net/http.(*conn).serve -> runtime.newstack (0.27s)"]
N77 -> N12 [label=" 0.27s" color="#b2b1ac" tooltip="runtime.unlock ... runtime.futex (0.27s)" labeltooltip="runtime.unlock ... runtime.futex (0.27s)" style="dotted"]
N71 -> N78 [label=" 0.25s" color="#b2b1ad" tooltip="net.(*netFD).accept ... syscall.Syscall6 (0.25s)" labeltooltip="net.(*netFD).accept ... syscall.Syscall6 (0.25s)" style="dotted"]
N66 -> N16 [label=" 0.25s" color="#b2b1ad" tooltip="runtime.gcDrain ... runtime.gentraceback (0.25s)" labeltooltip="runtime.gcDrain ... runtime.gentraceback (0.25s)" style="dotted"]
N42 -> N46 [label=" 0.23s" color="#b2b1ad" tooltip="github.com/json-iterator/go.(*Iterator).ReadString ... runtime.growslice (0.23s)" labeltooltip="github.com/json-iterator/go.(*Iterator).ReadString ... runtime.growslice (0.23s)" style="dotted"]
N39 -> N45 [label=" 0.22s" color="#b2b1ad" tooltip="net/textproto.(*Reader).ReadMIMEHeader ... runtime.slicebytetostring (0.22s)" labeltooltip="net/textproto.(*Reader).ReadMIMEHeader ... runtime.slicebytetostring (0.22s)" style="dotted"]
N69 -> N77 [label=" 0.22s\n (inline)" color="#b2b1ad" tooltip="runtime.(*mheap).freeSpan.func1 -> runtime.unlock (0.22s)" labeltooltip="runtime.(*mheap).freeSpan.func1 -> runtime.unlock (0.22s)"]
N26 -> N4 [label=" 0.21s" color="#b2b1ad" tooltip="runtime.(*sweepLocked).sweep ... runtime.systemstack (0.21s)" labeltooltip="runtime.(*sweepLocked).sweep ... runtime.systemstack (0.21s)" style="dotted"]
N58 -> N3 [label=" 0.21s" color="#b2b1ad" tooltip="runtime.mapassign ... runtime.mallocgc (0.21s)" labeltooltip="runtime.mapassign ... runtime.mallocgc (0.21s)" style="dotted"]
N4 -> N69 [label=" 0.21s" color="#b2b1ad" tooltip="runtime.systemstack -> runtime.(*mheap).freeSpan.func1 (0.21s)" labeltooltip="runtime.systemstack -> runtime.(*mheap).freeSpan.func1 (0.21s)"]
N2 -> N11 [label=" 0.20s" color="#b2b1ae" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... runtime.newobject (0.20s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... runtime.newobject (0.20s)" style="dotted"]
N39 -> N56 [label=" 0.19s" color="#b2b1ae" tooltip="net/textproto.(*Reader).ReadMIMEHeader ... runtime.mapaccess1_faststr (0.19s)" labeltooltip="net/textproto.(*Reader).ReadMIMEHeader ... runtime.mapaccess1_faststr (0.19s)" style="dotted"]
N25 -> N11 [label=" 0.18s\n (inline)" color="#b2b1ae" tooltip="runtime.mapassign_faststr -> runtime.newobject (0.18s)" labeltooltip="runtime.mapassign_faststr -> runtime.newobject (0.18s)"]
N28 -> N11 [label=" 0.17s" color="#b2b1ae" tooltip="net/http.readRequest ... runtime.newobject (0.17s)" labeltooltip="net/http.readRequest ... runtime.newobject (0.17s)" style="dotted"]
N58 -> N11 [label=" 0.17s\n (inline)" color="#b2b1ae" tooltip="runtime.mapassign -> runtime.newobject (0.17s)" labeltooltip="runtime.mapassign -> runtime.newobject (0.17s)"]
N21 -> N25 [label=" 0.16s" color="#b2b1ae" tooltip="github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 -> runtime.mapassign_faststr (0.16s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 -> runtime.mapassign_faststr (0.16s)"]
N76 -> N20 [label=" 0.16s" color="#b2b1ae" tooltip="runtime.copystack -> runtime.memmove (0.16s)" labeltooltip="runtime.copystack -> runtime.memmove (0.16s)"]
N5 -> N20 [label=" 0.15s" color="#b2b1af" tooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... runtime.memmove (0.15s)" labeltooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload ... runtime.memmove (0.15s)" style="dotted"]
N39 -> N25 [label=" 0.15s" color="#b2b1af" tooltip="net/textproto.(*Reader).ReadMIMEHeader -> runtime.mapassign_faststr (0.15s)" labeltooltip="net/textproto.(*Reader).ReadMIMEHeader -> runtime.mapassign_faststr (0.15s)"]
N70 -> N13 [label=" 0.14s" color="#b2b1af" tooltip="github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields -> runtime.makeslice (0.14s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/logger.(*ZapAdapter).fields -> runtime.makeslice (0.14s)"]
N35 -> N13 [label=" 0.14s" color="#b2b1af" tooltip="sync.(*Pool).Put ... runtime.makeslice (0.14s)" labeltooltip="sync.(*Pool).Put ... runtime.makeslice (0.14s)" style="dotted"]
N18 -> N11 [label=" 0.13s" color="#b2b1af" tooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... runtime.newobject (0.13s)" labeltooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... runtime.newobject (0.13s)" style="dotted"]
N18 -> N6 [label=" 0.13s" color="#b2b1af" tooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... sync.(*Pool).Get (0.13s)" labeltooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... sync.(*Pool).Get (0.13s)" style="dotted"]
N65 -> N57 [label=" 0.13s" color="#b2b1af" tooltip="net/http.Header.Clone ... runtime.mapiternext (0.13s)" labeltooltip="net/http.Header.Clone ... runtime.mapiternext (0.13s)" style="dotted"]
N54 -> N79 [label=" 0.13s" color="#b2b1af" tooltip="runtime.(*mcentral).cacheSpan ... runtime.sweepone (0.13s)" labeltooltip="runtime.(*mcentral).cacheSpan ... runtime.sweepone (0.13s)" style="dotted"]
N8 -> N31 [label=" 0.13s\n (inline)" color="#b2b1af" tooltip="runtime.findrunnable ... runtime.lock (0.13s)" labeltooltip="runtime.findrunnable ... runtime.lock (0.13s)" style="dotted"]
N71 -> N60 [label=" 0.12s" color="#b2b2af" tooltip="net.(*netFD).accept ... runtime.epollctl (0.12s)" labeltooltip="net.(*netFD).accept ... runtime.epollctl (0.12s)" style="dotted"]
N9 -> N74 [label=" 0.12s" color="#b2b2af" tooltip="syscall.Syscall ... runtime.casgstatus (0.12s)" labeltooltip="syscall.Syscall ... runtime.casgstatus (0.12s)" style="dotted"]
N18 -> N42 [label=" 0.11s" color="#b2b2b0" tooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode -> github.com/json-iterator/go.(*Iterator).ReadString (0.11s)" labeltooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode -> github.com/json-iterator/go.(*Iterator).ReadString (0.11s)"]
N2 -> N3 [label=" 0.11s" color="#b2b2b0" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... runtime.mallocgc (0.11s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).ServeHTTP ... runtime.mallocgc (0.11s)" style="dotted"]
N21 -> N11 [label=" 0.11s" color="#b2b2b0" tooltip="github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 ... runtime.newobject (0.11s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/middleware/prometheus.(*Plugin).Middleware.func1 ... runtime.newobject (0.11s)" style="dotted"]
N8 -> N53 [label=" 0.11s" color="#b2b2b0" tooltip="runtime.findrunnable -> runtime.checkTimers (0.11s)" labeltooltip="runtime.findrunnable -> runtime.checkTimers (0.11s)"]
N25 -> N3 [label=" 0.11s" color="#b2b2b0" tooltip="runtime.mapassign_faststr ... runtime.mallocgc (0.11s)" labeltooltip="runtime.mapassign_faststr ... runtime.mallocgc (0.11s)" style="dotted"]
N5 -> N11 [label=" 0.10s" color="#b2b2b0" tooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload -> runtime.newobject (0.10s)" labeltooltip="github.com/spiral/roadrunner/v2/worker.(*SyncWorkerImpl).execPayload -> runtime.newobject (0.10s)"]
N62 -> N11 [label=" 0.10s" color="#b2b2b0" tooltip="net.(*conn).Read -> runtime.newobject (0.10s)" labeltooltip="net.(*conn).Read -> runtime.newobject (0.10s)"]
N24 -> N40 [label=" 0.10s" color="#b2b2b0" tooltip="net/http.(*Server).Serve ... internal/poll.(*FD).Write (0.10s)" labeltooltip="net/http.(*Server).Serve ... internal/poll.(*FD).Write (0.10s)" style="dotted"]
N24 -> N6 [label=" 0.10s" color="#b2b2b0" tooltip="net/http.(*Server).Serve ... sync.(*Pool).Get (0.10s)" labeltooltip="net/http.(*Server).Serve ... sync.(*Pool).Get (0.10s)" style="dotted"]
N65 -> N13 [label=" 0.10s" color="#b2b2b0" tooltip="net/http.Header.Clone -> runtime.makeslice (0.10s)" labeltooltip="net/http.Header.Clone -> runtime.makeslice (0.10s)"]
N9 -> N4 [label=" 0.10s" color="#b2b2b0" tooltip="syscall.Syscall ... runtime.systemstack (0.10s)" labeltooltip="syscall.Syscall ... runtime.systemstack (0.10s)" style="dotted"]
N51 -> N3 [label=" 0.09s" color="#b2b2b0" tooltip="github.com/json-iterator/go.(*frozenConfig).Marshal -> runtime.mallocgc (0.09s)" labeltooltip="github.com/json-iterator/go.(*frozenConfig).Marshal -> runtime.mallocgc (0.09s)"]
N6 -> N11 [label=" 0.09s" color="#b2b2b0" tooltip="sync.(*Pool).Get ... runtime.newobject (0.09s)" labeltooltip="sync.(*Pool).Get ... runtime.newobject (0.09s)" style="dotted"]
N65 -> N25 [label=" 0.08s" color="#b2b2b0" tooltip="net/http.Header.Clone -> runtime.mapassign_faststr (0.08s)" labeltooltip="net/http.Header.Clone -> runtime.mapassign_faststr (0.08s)"]
N46 -> N27 [label=" 0.08s" color="#b2b2b0" tooltip="runtime.growslice -> runtime.memclrNoHeapPointers (0.08s)" labeltooltip="runtime.growslice -> runtime.memclrNoHeapPointers (0.08s)"]
N18 -> N57 [label=" 0.07s" color="#b2b2b0" tooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... runtime.mapiternext (0.07s)" labeltooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... runtime.mapiternext (0.07s)" style="dotted"]
N49 -> N56 [label=" 0.07s" color="#b2b2b0" tooltip="net/http.Header.writeSubset ... runtime.mapaccess1_faststr (0.07s)" labeltooltip="net/http.Header.writeSubset ... runtime.mapaccess1_faststr (0.07s)" style="dotted"]
N34 -> N53 [label=" 0.07s" color="#b2b2b0" tooltip="runtime.schedule -> runtime.checkTimers (0.07s)" labeltooltip="runtime.schedule -> runtime.checkTimers (0.07s)"]
N45 -> N20 [label=" 0.07s" color="#b2b2b0" tooltip="runtime.slicebytetostring -> runtime.memmove (0.07s)" labeltooltip="runtime.slicebytetostring -> runtime.memmove (0.07s)"]
N18 -> N20 [label=" 0.06s" color="#b2b2b1" tooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... runtime.memmove (0.06s)" labeltooltip="github.com/json-iterator/go.(*sortKeysMapEncoder).Encode ... runtime.memmove (0.06s)" style="dotted"]
N15 -> N20 [label=" 0.06s" color="#b2b2b1" tooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... runtime.memmove (0.06s)" labeltooltip="github.com/spiral/goridge/v3/internal.ReceiveFrame ... runtime.memmove (0.06s)" style="dotted"]
N7 -> N6 [label=" 0.06s" color="#b2b2b1" tooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... sync.(*Pool).Get (0.06s)" labeltooltip="github.com/spiral/roadrunner-plugins/v2/http/handler.(*Handler).Write ... sync.(*Pool).Get (0.06s)" style="dotted"]
N41 -> N20 [label=" 0.06s" color="#b2b2b1" tooltip="net/http.(*chunkWriter).writeHeader ... runtime.memmove (0.06s)" labeltooltip="net/http.(*chunkWriter).writeHeader ... runtime.memmove (0.06s)" style="dotted"]
N43 -> N58 [label=" 0.06s" color="#b2b2b1" tooltip="net/http.(*conn).readRequest ... runtime.mapassign (0.06s)" labeltooltip="net/http.(*conn).readRequest ... runtime.mapassign (0.06s)" style="dotted"]
N43 -> N6 [label=" 0.06s" color="#b2b2b1" tooltip="net/http.(*conn).readRequest ... sync.(*Pool).Get (0.06s)" labeltooltip="net/http.(*conn).readRequest ... sync.(*Pool).Get (0.06s)" style="dotted"]
N36 -> N20 [label=" 0.05s" color="#b2b2b1" tooltip="bufio.(*Writer).Write -> runtime.memmove (0.05s)" labeltooltip="bufio.(*Writer).Write -> runtime.memmove (0.05s)"]
N51 -> N35 [label=" 0.05s" color="#b2b2b1" tooltip="github.com/json-iterator/go.(*frozenConfig).Marshal ... sync.(*Pool).Put (0.05s)" labeltooltip="github.com/json-iterator/go.(*frozenConfig).Marshal ... sync.(*Pool).Put (0.05s)" style="dotted"]
N71 -> N11 [label=" 0.05s" color="#b2b2b1" tooltip="net.(*netFD).accept ... runtime.newobject (0.05s)" labeltooltip="net.(*netFD).accept ... runtime.newobject (0.05s)" style="dotted"]
N34 -> N74 [label=" 0.05s" color="#b2b2b1" tooltip="runtime.schedule ... runtime.casgstatus (0.05s)" labeltooltip="runtime.schedule ... runtime.casgstatus (0.05s)" style="dotted"]
}

rustatian · 2021-12-22T15:23:33Z

rustatian
Dec 22, 2021
Maintainer

So, first of all - thank you for working on this. According to the System Performance, Enterprise and the Cloud you are doing the main error in the investigation. You are trying to find a latency problem in the path which is only 1-2-5% from the path of the request. RR part in the requests is very small. According to my benches and various articles, the single syscall cost is around 180ns. So, in the 20ms, RR takes 1-2ms (w/o middleware for sure).
As you can see on the screenshot, the RR latency (including hello-world PHP worker) takes 1.5ms

So, thank you for the investigation, but I am convinced, that you are searching on the wrong path.

8 replies

dorantor Dec 22, 2021
Author

Ok, thx. Will give it a try. Can it be run w/o VMs? As an example, like this:

rr serve -d &
rr serve -d &
rr serve -d &
# ..or, same result can be achieved with 3 tmux|screen consoles

Will it work as expected? Assuming configuration have TCP_REUSEPORT enabled.
According to

You can even start 2-3 RR instances

it should, so just making sure I understand correctly :)

rustatian Dec 22, 2021
Maintainer

Yep, you understand correctly. The TCP_REUSEPORT exists in the kernel since v3.9, so, I'm pretty sure, that you have this feature in your Linux distribution. You don't need to turn it on somehow manually, this is just a passive socket option which RR enables automatically, you can read more here: https://lwn.net/Articles/542629/

rustatian Dec 22, 2021
Maintainer

@dorantor Note: we have a discord server, where you can ask the questions to the community as well: https://discord.gg/TFeEmCs

rustatian Dec 22, 2021
Maintainer

Also, make sure, that you're running w/o -d option (rr serve -d).

rustatian Dec 27, 2021
Maintainer

@dorantor Friendly ping) Do you have any results after running multiple RR instances?

rustatian · 2022-01-18T08:43:32Z

rustatian
Jan 18, 2022
Maintainer

@dorantor Friendly ping 😃 Any updates?

0 replies

lanphan · 2022-03-26T06:30:05Z

lanphan
Mar 26, 2022

Hello @dorantor ,

I'm curious about your experimental, do you have any update on this topic?

Hi @rustatian ,

I discovered that Opcache is enabled on our system, but it doesn't optimize or enhance anything, some important metrics about opcache are always 0:

(noted that I set max_jobs of RR to 100 already, and ran multiple requests)

Cache hits => 0
Cache misses => 0
Wasted memory => 0
Cached scripts => 0
Cached keys => 0

1 thing I found that you mentioned all source code of workers are kept in memory, does it mean we don't need opcache anymore?

Thanks.

2 replies

rustatian Mar 26, 2022
Maintainer

I guess Opcache is an independent feature. I mean, it should work independently from RR. You may ask guys in our discord channel: https://discord.gg/TFeEmCs

lanphan Mar 26, 2022

thank @rustatian ,
I joined Discord and posted my question there

lanphan · 2022-03-26T06:45:57Z

lanphan
Mar 26, 2022

There is 1 article I found comparing perf between pure PHP vs. [RoadRunner + php] here: https://discourse.world/h/2019/10/22/Trying-preload(PHP-7.4)and-RoadRunner

I'm looking forward to have more advice from @rustatian @dorantor if you can enable Opcache when running with RoadRunner.

Thanks.

1 reply

rustatian Mar 26, 2022
Maintainer

This is a rather old article with RRv1 used in it. And it's compared to the PHP-FPM (I guess this is not a pure PHP). Modern RR (v2) outperforms RRv1.

RoadRunner

[Q] Performance(RPS) is lower then expected. Why and what to do? #876

dorantor Dec 21, 2021

Replies: 10 comments · 27 replies

rustatian Dec 21, 2021 Maintainer

rustatian Dec 21, 2021 Maintainer

dorantor Dec 21, 2021 Author

dorantor Dec 21, 2021 Author

rustatian Dec 21, 2021 Maintainer

dorantor Dec 21, 2021 Author

dorantor Dec 21, 2021 Author

rustatian Dec 21, 2021 Maintainer

dorantor Dec 21, 2021 Author

rustatian Dec 21, 2021 Maintainer

dorantor Dec 22, 2021 Author

dorantor Dec 21, 2021 Author

dorantor Dec 21, 2021 Author

dorantor Dec 22, 2021 Author

dorantor Dec 22, 2021 Author

rustatian Dec 22, 2021 Maintainer

dorantor Dec 22, 2021 Author

rustatian Dec 22, 2021 Maintainer

dorantor Dec 22, 2021 Author

rustatian Dec 22, 2021 Maintainer

rustatian Dec 22, 2021 Maintainer

rustatian Dec 22, 2021 Maintainer

rustatian Dec 27, 2021 Maintainer

rustatian Jan 18, 2022 Maintainer

lanphan Mar 26, 2022

rustatian Mar 26, 2022 Maintainer

lanphan Mar 26, 2022

lanphan Mar 26, 2022

rustatian Mar 26, 2022 Maintainer

dorantor
Dec 21, 2021

Replies: 10 comments 27 replies

rustatian
Dec 21, 2021
Maintainer

rustatian
Dec 21, 2021
Maintainer

dorantor Dec 21, 2021
Author

dorantor
Dec 21, 2021
Author

rustatian
Dec 21, 2021
Maintainer

dorantor
Dec 21, 2021
Author

dorantor Dec 21, 2021
Author

rustatian Dec 21, 2021
Maintainer

dorantor Dec 21, 2021
Author

rustatian Dec 21, 2021
Maintainer

dorantor Dec 22, 2021
Author

dorantor
Dec 21, 2021
Author

dorantor Dec 21, 2021
Author

dorantor Dec 22, 2021
Author

dorantor Dec 22, 2021
Author

rustatian Dec 22, 2021
Maintainer

dorantor Dec 22, 2021
Author

rustatian
Dec 22, 2021
Maintainer

dorantor Dec 22, 2021
Author

rustatian Dec 22, 2021
Maintainer

rustatian Dec 22, 2021
Maintainer

rustatian Dec 22, 2021
Maintainer

rustatian Dec 27, 2021
Maintainer

rustatian
Jan 18, 2022
Maintainer

lanphan
Mar 26, 2022

rustatian Mar 26, 2022
Maintainer

lanphan
Mar 26, 2022

rustatian Mar 26, 2022
Maintainer