Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

["Randy MacLeod" <randy.macleod@windriver.com>]

On 2021-04-15 4:48 p.m., Randy MacLeod wrote:
> On 2021-04-15 1:55 p.m., Randy MacLeod wrote:
>> On 2021-04-15 11:55 a.m., Richard Purdie wrote:
>>> On Thu, 2021-04-15 at 11:31 -0400, Sakib Sajal wrote:
>>>> On 2021-04-15 9:52 a.m., Richard Purdie wrote:
>>>>> [Please note: This e-mail is from an EXTERNAL e-mail address]
>>>>>
>>>>> On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
>>>>>> collect-data template can run arbitrary commands/scripts
>>>>>> on a regular basis and logs the output in a file.
>>>>>>
>>>>>> See oe-core for more details:
>>>>>>       edb7098e9e buildstats.bbclass: add functionality to collect 
>>>>>> build system stats
>>>>>>
>>>>>> Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
>>>>>> Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
>>>>>> ---
>>>>>>    config.json | 7 +++++++
>>>>>>    1 file changed, 7 insertions(+)
>>>>>>
>>>>>> diff --git a/config.json b/config.json
>>>>>> index 5bfa240..c43d231 100644
>>>>>> --- a/config.json
>>>>>> +++ b/config.json
>>>>>> @@ -87,6 +87,13 @@
>>>>>>                    "SANITYTARGETS" : 
>>>>>> "core-image-full-cmdline:do_testimage 
>>>>>> core-image-sato:do_testimage core-image-sato-sdk:do_testimage"
>>>>>>                }
>>>>>>            },
>>>>>> +     "collect-data" : {
>>>>>> +            "extravars" : [
>>>>>> +                "BB_HEARTBEAT_EVENT = '10'",
>>>>>> +                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
>>>>>> +                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
>>>>>> +            ]
>>>>>> +        },
>>>>> Is the template used anywhere? I can't remember if we support 
>>>>> nesting templates in which
>>>>> case this is useful, or not?
>>
>> We were using it for testing on the YP AB and thought it would be
>> useful if at some point the monitoring was dropped from the
>> default config.
>>
>> I think we can just add it later if needed.
>
> Richard,
>
> I think that the web server for:
>   https://autobuilder.yocto.io/pub/non-release/
> runs every 30 seconds via cron so if you are happy with
> this crude dd trigger once things have soaked in master-next
> and we want to gather some data overnight, could you merge to master?
>
>
> I ran a simpler test with fewer io stressors from:
> $ stress -hdd N
> and have attached a graph with up to 3000! stressors that
> we looked at this morning and another with up to 35 stressors.
>
> It's a crude indicators but once we get beyond 18-20 io stressors
> on the system I tested (48 cores, 128 GB RAM, 12 TB magnetic disk)
> dd time become erratic.
>
> Running qemu from tmpfs has clearly helped.
> Let's gather some data and decide if we want to spend more time
> learning how to monitor the system to tune how we are using it.
>
> ../Randy

Thanks for fixing the fall-out due to assumptions in other tests.
Is the system back to normal and operational now?


What was the impact of running the heartbeat and the dd test every
10 seconds on the system build performance?

Should we  increase the interval to 30, 60, ore more seconds?


I spent some time looking at the first bit of data along with
Sakib and Saul from time to time.

General conclusions:

1. It seems like ALL triggers involve oe-selftest being active.

2. xz might be a problem but we're not sure yet.

3. We need more data and tools and time to think about it.


To Do:

1. increase top cmdline length from 512 to  16K

2. sometimes we see:

      Command '['oe-time-dd-test.sh', '100']' timed out after 10.0 seconds

That should not happen so we should understand why and either increase
the time between runs or fix the tooling. This seems to happen under load
so it's hiding the interesting data that we are looking for!

3. tail the cooker console in addition to top. Present that before top.

     It would be nice to have a top equivalent for bitbake.




We did collect some triggered host data last night as seen in:

https://autobuilder.yocto.io/pub/non-release/

https://autobuilder.yocto.io/pub/non-release/20210415-16/

Only one a-full build was run. There were 10 log files produced.

There were 21 times that the dd time exceeded the 5 second limit
out of a total of 21581 (or so!) invocations and those triggers we
captured by 10 log files:

testresults/beaglebone-alt/2021-04-16--00-19/host_stats_0_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_2_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_4_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_6_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_8_top.txt
testresults/qemuarm/2021-04-16--00-02/host_stats_0_top.txt
testresults/qemuarm/2021-04-16--00-02/host_stats_1_top.txt
testresults/qemumips-alt/2021-04-15--23-36/host_stats_1_top.txt
testresults/qemumips64/2021-04-16--02-46/host_stats_0_top.txt
testresults/qemux86-world/2021-04-16--00-00/host_stats_0_top.txt


We knew that our naming convention needed work in that the files
are generically named and differ only by the directory datastamp and,
where the logs contain 'top' output or not the _top suffix.  We'd like 
to help
whoever is looking at the data understand what the context of
the build was. That's not clear to Sakib and I given that we are YP AB 
newbies still.
Do you have any suggestions about what the directory structure or file 
naming convention should be?
The other thing need to do is correlate these higher latency times
with the intermittent problems we've encountered. We can do that manually
I support via the SWAT team but ideally there would be an automated process.


More quick analysis...

The number of times that top ran per log file:

$ grep "^top - " `fd _top autobuilder.yocto.io/` | cut -d":" -f1 | uniq 
-c | \
     sed -e 's|autobuilder.yocto.io/pub/non-release/20210415-16/||'
       2 testresults/beaglebone-alt/2021-04-16--00-19/host_stats_0_top.txt
       3 testresults/qa-extras2/2021-04-15--22-43/host_stats_2_top.txt
       1 testresults/qa-extras2/2021-04-15--22-43/host_stats_4_top.txt
       2 testresults/qa-extras2/2021-04-15--22-43/host_stats_6_top.txt
       1 testresults/qa-extras2/2021-04-15--22-43/host_stats_8_top.txt
       5 testresults/qemuarm/2021-04-16--00-02/host_stats_0_top.txt
       2 testresults/qemuarm/2021-04-16--00-02/host_stats_1_top.txt
       1 testresults/qemumips-alt/2021-04-15--23-36/host_stats_1_top.txt
       2 testresults/qemumips64/2021-04-16--02-46/host_stats_0_top.txt
       2 testresults/qemux86-world/2021-04-16--00-00/host_stats_0_top.txt
some of these are duplicates in that the different steps _2,4,6,8 above

A little shell hacking can produce one file per top output with
ample access to stackoverflow!

COUNTER=1
for i in `fd _top`;
    do for j in `grep "^top - " $i | cut -c 7-15`; do
         sed -n "/top - ${j}/,/Event Time:/p" $i >> 
host-stats-$j--$COUNTER.log;
         ((COUNTER++));
    done;
done

This works because the first line of time is similar to:
    top - 15:40:53 up 2 days, 22:17,  1 user,  load average: 0.36, 0.58, 
0.85
so cutting out chars 7-15 gives a fairly uniq timestamp string for the 
filename and
adding the counter makes it unique.

Now we have 21 log files:

$ ls host-stats-2* | wc -l
21

How big are these files, ie how many process/kernel threads were running
when top ran?

$ wc -l host-stats-2* | sort -n
     757 host-stats-22:12:32--17.log
     778 host-stats-22:18:21--8.log
     784 host-stats-21:59:42--5.log
     785 host-stats-21:59:42--12.log
     792 host-stats-22:18:01--7.log
     800 host-stats-22:18:21--14.log
     811 host-stats-22:07:40--13.log
     812 host-stats-22:07:59--6.log
     821 host-stats-21:56:21--3.log
     850 host-stats-21:59:33--11.log
     856 host-stats-21:59:33--4.log
     869 host-stats-22:29:49--16.log
     884 host-stats-22:29:14--9.log
     886 host-stats-22:29:36--15.log
     981 host-stats-21:55:40--10.log
     985 host-stats-22:47:27--2.log
     987 host-stats-22:47:27--21.log
    1124 host-stats-22:37:33--1.log
    1193 host-stats-22:37:26--20.log
    1304 host-stats-23:19:14--19.log
    1321 host-stats-23:18:57--18.log
   19380 total

I noticed that several but not all log files were running xz with args like:

     xz -a --memlimit=50% --threads=56

$ for i in `ls host-stats-2*`; do echo -n $i ": "; grep "xz " $i | wc 
-l; done
host-stats-21:55:40--10.log : 28
host-stats-21:56:21--3.log : 4
host-stats-21:59:33--11.log : 1
host-stats-21:59:33--4.log : 1
host-stats-21:59:42--12.log : 1
host-stats-21:59:42--5.log : 1
host-stats-22:07:40--13.log : 2
host-stats-22:07:59--6.log : 2
host-stats-22:12:32--17.log : 0
host-stats-22:18:01--7.log : 6
host-stats-22:18:21--14.log : 3
host-stats-22:18:21--8.log : 3
host-stats-22:29:14--9.log : 1
host-stats-22:29:36--15.log : 0
host-stats-22:29:49--16.log : 0
host-stats-22:37:26--20.log : 56
host-stats-22:37:33--1.log : 16
host-stats-22:47:27--21.log : 0
host-stats-22:47:27--2.log : 0
host-stats-23:18:57--18.log : 0
host-stats-23:19:14--19.log : 18

In this case, I don't think it's a problem but if we had several packages
running xz like that at once with a limit of 50% of memory each,
that could be a problem. Has anyone looked at the time impact of
say reducing the number of threads to 32 and the memory limit to
15% ?


All of the top output logs seems to be running oe-selftest:

$ for i in host-stats-2*; do grep -H -c "DISPLAY.*oe-selftest " $i ; done
host-stats-21:55:40--10.log:1
host-stats-21:56:21--3.log:1
host-stats-21:59:33--11.log:1
host-stats-21:59:33--4.log:1
host-stats-21:59:42--12.log:1
host-stats-21:59:42--5.log:1
host-stats-22:07:40--13.log:1
host-stats-22:07:59--6.log:1
host-stats-22:12:32--17.log:1
host-stats-22:18:01--7.log:1
host-stats-22:18:21--14.log:1
host-stats-22:18:21--8.log:1
host-stats-22:29:14--9.log:1
host-stats-22:29:36--15.log:1
host-stats-22:29:49--16.log:1
host-stats-22:37:26--20.log:1
host-stats-22:37:33--1.log:1
host-stats-22:47:27--21.log:1
host-stats-22:47:27--2.log:1
host-stats-23:18:57--18.log:2
host-stats-23:19:14--19.log:2
$ for i in host-stats-2*; do grep -H -c "DISPLAY.*oe-selftest " $i ; 
done   | wc -l
21

Yikes, that seems like more than just random chance.


The logs do not seem to be duplicates in that there isn't a single cluster
of identical or similar timestamps although some are close and are
likely from the same file. That said they certainly don't seem to
be spread out uniformly over time and that's what we all expect
in that the system response time is okay for much of the time and
is poor for quite a while every now and then.

$ for i in host-stats-2*; do echo -n $i ": "; head -1 $i | cut -c -15; done
host-stats-21:55:40--10.log : top - 21:55:40
host-stats-21:56:21--3.log   : top - 21:56:21
host-stats-21:59:33--11.log : top - 21:59:33
host-stats-21:59:33--4.log   : top - 21:59:33
host-stats-21:59:42--12.log : top - 21:59:42
host-stats-21:59:42--5.log   : top - 21:59:42
host-stats-22:07:40--13.log : top - 22:07:40
host-stats-22:07:59--6.log   : top - 22:07:59
host-stats-22:12:32--17.log : top - 22:12:32
host-stats-22:18:01--7.log   : top - 22:18:01
host-stats-22:18:21--14.log : top - 22:18:21
host-stats-22:18:21--8.log   : top - 22:18:21
host-stats-22:29:14--9.log   : top - 22:29:14
host-stats-22:29:36--15.log : top - 22:29:36
host-stats-22:29:49--16.log : top - 22:29:49
host-stats-22:37:26--20.log : top - 22:37:26
host-stats-22:37:33--1.log   : top - 22:37:33
host-stats-22:47:27--21.log : top - 22:47:27
host-stats-22:47:27--2.log   : top - 22:47:27
host-stats-23:18:57--18.log : top - 23:18:57
host-stats-23:19:14--19.log : top - 23:19:14


All for now.

../Randy


>
>>
>> ../Randy
>>>>>
>>>>> Cheers,
>>>>>
>>>>> Richard
>>>>
>>>> The template is not used anywhere, yet, the initial patchset 
>>>> enables the
>>>> data collection by default.
>>>>
>>>> I have left the template in case the data collection is removed from
>>>> defaults and need to be used on a case by case basis.
>>>>
>>>> I am not entirely sure if nesting templates work. I have not seen any
>>>> examples of it, neither did i try it myself. If nesting does work, the
>>>> template should be useful.
>>>
>>> I had a quick look at the code and sadly, it doesn't appear I 
>>> implemented
>>> nesting so this wouldn't be that useful as things stand.
>>>
>>> Cheers,
>>>
>>> Richard
>>>
>>>
>>>
>>>
>>> 
>>>
>>
>>
>
>

-- 
# Randy MacLeod
# Wind River Linux