[CRIU] Technical question

Rami Addad Ramy.ak at hotmail.fr
Wed Mar 1 07:19:09 PST 2017 

Dear all, 
Thanks a lot again 


Sent from my iPhone

> On Mar 1, 2017, at 4:51 PM, Pavel Emelyanov <xemul at virtuozzo.com> wrote:
> 
>> On 03/01/2017 03:35 PM, Rami Addad wrote:
>> Dear all,
>> 
>> as you told me i reduced the verbosity but i steel obtain the same time.
> 
> Yes. As I wrote in the previous e-mail the root cause of the slow
> dump is collecting cgroups for tasks. We'll try to dive deeper to
> find out why this happens.
> 
> -- Pavel
> 
>> Best Regards,
>> 
>> 
>> 
>> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>> *De :* Pavel Emelyanov <xemul at virtuozzo.com>
>> *Envoyé :* mardi 28 février 2017 17:23
>> *À :* Rami Addad; CRIU; Tycho Andersen
>> *Objet :* Re: [CRIU] Technical question
>> 
>>> On 02/28/2017 08:03 PM, Pavel Emelyanov wrote:
>>>> On 02/28/2017 07:52 PM, Rami Addad wrote:
>>>> Rami Addad a partagé un fichier OneDrive avec vous. Pour l’afficher, cliquez sur le lien ci-dessous.
>>>> 
>>>> <https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo>
>> <https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo>    
>> ramy copy.txt <https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo>
>> Partagé via OneDrive
>> 
>> 
>> 
>>>> 
>>>> ramy copy.txt <https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo>
>> <https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo>    
>> ramy copy.txt <https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo>
>> Partagé via OneDrive
>> 
>> 
>> 
>>>> 
>>>> 
>>>> Hi pavel,
>>>> 
>>>> thanks a lot again 
>>>> 
>>>> this is the entire dump.log file 
>>> 
>>> Don't drop criu at openvz.org from Cc, please.
>>> 
>>> So, I don't see huge gaps in log file, at the first glance it looks like
>>> the dump just makes lots of steps to proceed.
>> 
>> Ah, I did some more analysis :) Tycho, I think you'd be interested.
>> 
>> First, the timestamps from logs were translated into relative times:
>> $ cat dump.log | egrep '^\([0-9]' | sed -e 's/[()]/ /g' | awk 'BEGIN{s=0.0}{printf("%.6f %s\n", $1-s, $0); s=$1}' > dump-rt.log
>> $ head dump-rt.log
>> 0.000018  00.000018  Version: 2.11.1  gitid 0
>> 0.000022  00.000040  Will do snapshot from ../2/
>> 0.000013  00.000053  Probing sock diag modules
>> ...
>> 
>> so the first column shows the amt of time spent in code since the previous line, not
>> since the very beginning.
>> 
>> Next, I've noticed the longest of them
>> 
>> $ cat dump-rt.log | egrep '^0\.[^0]'
>> <this was empty>
>> $ cat dump-rt.log | egrep '^0\.0[^0]'
>> 0.013191  00.040647  cg: adding cgroup /proc/self/fd/23/lxc/u1
>> 0.015798  00.056679  cg: adding cgroup /proc/self/fd/23/lxc/u1
>> 0.019688  00.076550  cg: adding cgroup /proc/self/fd/23/lxc/u1
>> ...
>> and it was 90% of this line.
>> 
>> Next I calculated the total time spent in this "adding cgroup" stuff
>> 
>> $ cat dump-rt.log | fgrep 'adding cg' | awk '{t+=$1}END{print t}'
>> 3.12338
>> 
>> So walking and collecting cgroups for tasks takes ~3.1 out of 3.4+
>> seconds for the dump.
>> 
>> -- Pavel
>> 
>> 
>>> Let's try reducing the verbosity and see what's happening again.
>>> 
>>> -- Pavel
>>> 
>>>> Best regards,
>>>> 
>>>> 
>>>> 
>>>> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>>>> *De :* Pavel Emelyanov <xemul at virtuozzo.com>
>>>> *Envoyé :* mardi 28 février 2017 16:33
>>>> *À :* Rami Addad; CRIU
>>>> *Objet :* Re: [CRIU] Technical question
>>>> 
>>>>> On 02/28/2017 07:17 PM, Rami Addad wrote:
>>>>> Rami Addad a partagé des fichiers OneDrive avec vous. Pour les afficher, cliquez sur les liens ci-dessous.
>>>>> 
>>>>> <https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi>
>>>> <https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi> 
>>>> statistic.txt <https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi>
>>>> Partagé via OneDrive
>>>> 
>>>> 
>>>> 
>>>>> 
>>>>> statistic.txt <https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi>
>>>> <https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi> 
>>>> statistic.txt <https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi>
>>>> Partagé via OneDrive
>>>> 
>>>> 
>>>> 
>>>>> 
>>>>> 
>>>>> <https://1drv.ms/u/s%21AnSrSEU9SGBag3x2OlbNwymfKbOk>
>>>>> 
>>>>> dump.sh <https://1drv.ms/u/s%21AnSrSEU9SGBag3x2OlbNwymfKbOk>
>>>>> 
>>>>> 
>>>>> Dear all,
>>>>> 
>>>>> 
>>>>> for the option  --track-mem we put it in every pre-dump and also in the last dump
>>>>> 
>>>>> and you could observe in the statistic.txt file that there are skipped page and also
>>>>> 
>>>>> the freezing time is small and all the others time are small only the frozen time is big
>>>>> 
>>>>> 
>>>>> 
>>>>> and there is the part of script in file dump.sh 
>>>>> 
>>>>> 
>>>>> 
>>>>> we think that we have took all the possibility but we always have this big time of dump
>>>> 
>>>> OK, here are the stats for final dump
>>>> 
>>>> "dump": {
>>>>                "freezing_time": 8017,
>>>>                "frozen_time": 4243423,
>>>>                "memdump_time": 21419,
>>>>                "memwrite_time": 5866,
>>>>                "pages_scanned": 258539,
>>>>                "pages_skipped_parent": 9985,
>>>>                "pages_written": 1356,
>>>>                "irmap_resolve": 0
>>>>            }
>>>> 
>>>> frozen time is 4 seconds, memdump time is 0.02 seconds, so the time
>>>> is spent somewhere else.
>>>> 
>>>> First -- try to reduce the verbosity of this final dump, don't use the -vvvvvv
>>>> option, leave it to be -v0.
>>>> Second, can you show your dump.log file with increased verbosity, there are
>>>> timestamps in it, they will help to understand where the time is spent.
>>>> 
>>>> -- Pavel
>>> 
>> 
>

More information about the CRIU mailing list