[CRIU] Technical question

[Pavel Emelyanov]

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
>> 
>