[CRIU] Technical question

[Pavel Emelyanov]

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>
>> 	
>> ramy copy.txt <https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo>
>> 	
>>
>> 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
>