Re: kernel 100% CPU, and ports-mgmt/poudriere-devel 'Inspecting ports tree for modifications to git checkout...' for an extraordinarily long time

On 9/2/23, Graham Perrin <grahamperrin@gmail.com> wrote:
> On 02/09/2023 10:17, Mateusz Guzik wrote:
>> On 9/2/23, Graham Perrin <grahamperrin@gmail.com> wrote:
>>> Some inspections are extraordinarily time-consuming. Others complete
>>> very quickly, as they should.
>>>
>>> One recent inspection took more than half an hour.
>>>
>>> Anyone else?
>>>
>>> A screenshot: <https://i.imgur.com/SK9qvfw.png>
>>>
>>> % pkg iinfo poudriere-devel
>>> poudriere-devel-3.3.99.20220831
>>> % uname -aKU
>>> FreeBSD mowa219-gjp4-8570p-freebsd 15.0-CURRENT FreeBSD 15.0-CURRENT
>>> amd64 1500000 #10 main-n265053-315ee00fa961-dirty: Mon Aug 28 06:22:31
>>> BST 2023
>>> grahamperrin@mowa219-gjp4-8570p-freebsd:/usr/obj/usr/src/amd64.amd64/sys/GENERIC-NODEBUG
>>>
>>> amd64 1500000 1500000
>>> %
>> get a flamegraph with dtrace
>>
>> https://github.com/brendangregg/FlameGraph
>
> Thanks! TIL, it's ported.
>
> Graph attached, as a PNG, although I don't know whether it'll be useful,
> because I began the trace /after/ the issue became observable.
>
> Will it be more meaningful to begin a trace and then reproduce the issue
> (before the trace ends)?
>
> ----
>
> root@mowa219-gjp4-8570p-freebsd:/tmp # dtrace -x stackframes=100 -n
> 'profile-997 /arg0/ { @[stack()] = count(); } tick-60s { exit(0); }' -o
> out.kern_stacks
> dtrace: description 'profile-997 ' matched 2 probes
> root@mowa219-gjp4-8570p-freebsd:/tmp # stackcollapse.pl out.kern_stacks
>  > out.kern_folded
> root@mowa219-gjp4-8570p-freebsd:/tmp # flamegraph.pl out.kern_folded >
> kernel.svg
> root@mowa219-gjp4-8570p-freebsd:/tmp #
>

Looks like you have a lot of unrelated traffic in there.

Run this script:
#pragma D option dynvarsize=32m

profile:::profile-997
/execname == "find"/
{
        @oncpu[stack(), "oncpu"] = count();
}

/*
 * The p_flag & 0x4 test filters out kernel threads.
 */

sched:::off-cpu
/execname == "find"/
{
        self->ts = timestamp;
}

sched:::on-cpu
/self->ts/
{
        @offcpu[stack(30), "offcpu"] = sum(timestamp - self->ts);
        self->ts = 0;
}

dtrace:::END
{
        normalize(@offcpu, 1000000);
        printa("%k\n%s\n%@d\n\n", @offcpu);
        printa("%k\n%s\n%@d\n\n", @oncpu);
}

dtrace -s script.d -o out

this can be fed to generate a flamegraph the same way; upload it to freefall

-- 
Mateusz Guzik <mjguzik gmail.com>