<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=Windows-1252">
<style type="text/css" style="display:none;"><!-- P {margin-top:0;margin-bottom:0;} --></style>
</head>
<body dir="ltr">
<div id="divtagdefaultwrapper" style="font-size:12pt;color:#000000;font-family:Calibri,Arial,Helvetica,sans-serif;" dir="ltr">
<p>Dear all,</p>
<p>as you told me i reduced the verbosity but i steel obtain the same time.</p>
<p>Best Regards,</p>
<br>
<br>
<div style="color: rgb(0, 0, 0);">
<div>
<hr tabindex="-1" style="display:inline-block; width:98%">
<div id="x_divRplyFwdMsg" dir="ltr"><font face="Calibri, sans-serif" color="#000000" style="font-size:11pt"><b>De :</b> Pavel Emelyanov <xemul@virtuozzo.com><br>
<b>Envoyé :</b> mardi 28 février 2017 17:23<br>
<b>À :</b> Rami Addad; CRIU; Tycho Andersen<br>
<b>Objet :</b> Re: [CRIU] Technical question</font>
<div> </div>
</div>
</div>
<font size="2"><span style="font-size:10pt;">
<div class="PlainText">On 02/28/2017 08:03 PM, Pavel Emelyanov wrote:<br>
> On 02/28/2017 07:52 PM, Rami Addad wrote:<br>
>> Rami Addad a partagé un fichier OneDrive avec vous. Pour l’afficher, cliquez sur le lien ci-dessous.<br>
>><br>
>> <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo" id="LPlnk769881|2:odcLink" previewremoved="true">https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo</a>>
<div id="LPBorder_GT|1:LPlnk769881[|2:odcLink|4:4]" style="margin-bottom: 20px; overflow: auto; width: 100%; text-indent: 0px;">
<table id="LPContainer_14883716453210.04874135998486406" cellspacing="0" style="width: 90%; background-color: rgb(255, 255, 255); position: relative; overflow: auto; padding-top: 20px; padding-bottom: 20px; margin-top: 20px; border-top: 1px dotted rgb(200, 200, 200); border-bottom: 1px dotted rgb(200, 200, 200);">
<tbody>
<tr valign="top" style="border-spacing: 0px;">
<td id="TextCell_14883716453220.06736057262294448" colspan="2" style="vertical-align: top; position: relative; padding: 0px; display: table-cell;">
<div id="LPRemovePreviewContainer_14883716453220.10262428036178561"></div>
<div id="LPOptionsContainer_14883716453220.12209724369170294"></div>
<table>
<tbody>
<tr valign="top" style="border-spacing: 0px;">
<td><a href="https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo" target="_blank" style="margin-right: 10px;"><img id="LPItemIcon_14883716453220.24739840502865507" src="https://r1.res.office365.com/owa/prem/images/dc-txt_40.png"></a></td>
<td>
<div id="LPTitle_14883716453230.05714715031708306" style="top: 0px; color: rgb(0, 120, 215); font-weight: normal; font-size: 21px; font-family: wf_segoe-ui_light, "Segoe UI Light", "Segoe WP Light", "Segoe UI", "Segoe WP", Tahoma, Arial, sans-serif; line-height: 21px;">
<a id="LPUrlAnchor_14883716453230.7180187514707939" href="https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo" target="_blank" style="text-decoration: none;">ramy copy.txt</a></div>
<div id="LPMetadata_14883716453230.6160839783297858" style="margin: 10px 0px 16px; color: rgb(102, 102, 102); font-weight: normal; font-family: wf_segoe-ui_normal, "Segoe UI", "Segoe WP", Tahoma, Arial, sans-serif; font-size: 14px; line-height: 14px;">
Partagé via OneDrive</div>
</td>
</tr>
</tbody>
</table>
</td>
</tr>
</tbody>
</table>
</div>
<br>
<br>
>> <br>
>> ramy copy.txt <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo" id="LPlnk669090|2:odcLink">https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo</a>>
<div id="LPBorder_GT|1:LPlnk669090[|2:odcLink|4:4]" style="margin-bottom: 20px; overflow: auto; width: 100%; text-indent: 0px;">
<table id="LPContainer_14883716453290.544502688710762" cellspacing="0" style="width: 90%; background-color: rgb(255, 255, 255); position: relative; overflow: auto; padding-top: 20px; padding-bottom: 20px; margin-top: 20px; border-top: 1px dotted rgb(200, 200, 200); border-bottom: 1px dotted rgb(200, 200, 200);">
<tbody>
<tr valign="top" style="border-spacing: 0px;">
<td id="TextCell_14883716453300.13922866301493997" colspan="2" style="vertical-align: top; position: relative; padding: 0px; display: table-cell;">
<div id="LPRemovePreviewContainer_14883716453300.9853555305444095"></div>
<div id="LPOptionsContainer_14883716453300.15145798669559296"></div>
<table>
<tbody>
<tr valign="top" style="border-spacing: 0px;">
<td><a href="https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo" target="_blank" style="margin-right: 10px;"><img id="LPItemIcon_14883716453300.549727844062275" src="https://r1.res.office365.com/owa/prem/images/dc-txt_40.png"></a></td>
<td>
<div id="LPTitle_14883716453300.33599438700178785" style="top: 0px; color: rgb(0, 120, 215); font-weight: normal; font-size: 21px; font-family: wf_segoe-ui_light, "Segoe UI Light", "Segoe WP Light", "Segoe UI", "Segoe WP", Tahoma, Arial, sans-serif; line-height: 21px;">
<a id="LPUrlAnchor_14883716453310.6284611722735611" href="https://1drv.ms/t/s%21AnSrSEU9SGBag31SvW9tTuVhHylo" target="_blank" style="text-decoration: none;">ramy copy.txt</a></div>
<div id="LPMetadata_14883716453310.6189682826428937" style="margin: 10px 0px 16px; color: rgb(102, 102, 102); font-weight: normal; font-family: wf_segoe-ui_normal, "Segoe UI", "Segoe WP", Tahoma, Arial, sans-serif; font-size: 14px; line-height: 14px;">
Partagé via OneDrive</div>
</td>
</tr>
</tbody>
</table>
</td>
</tr>
</tbody>
</table>
</div>
<br>
<br>
>> <br>
>><br>
>> Hi pavel,<br>
>><br>
>> thanks a lot again <br>
>><br>
>> this is the entire dump.log file <br>
> <br>
> Don't drop criu@openvz.org from Cc, please.<br>
> <br>
> So, I don't see huge gaps in log file, at the first glance it looks like<br>
> the dump just makes lots of steps to proceed.<br>
<br>
Ah, I did some more analysis :) Tycho, I think you'd be interested.<br>
<br>
First, the timestamps from logs were translated into relative times:<br>
$ 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<br>
$ head dump-rt.log<br>
0.000018 00.000018 Version: 2.11.1 gitid 0 <br>
0.000022 00.000040 Will do snapshot from ../2/<br>
0.000013 00.000053 Probing sock diag modules<br>
...<br>
<br>
so the first column shows the amt of time spent in code since the previous line, not<br>
since the very beginning.<br>
<br>
Next, I've noticed the longest of them<br>
<br>
$ cat dump-rt.log | egrep '^0\.[^0]'<br>
<this was empty><br>
$ cat dump-rt.log | egrep '^0\.0[^0]'<br>
0.013191 00.040647 cg: adding cgroup /proc/self/fd/23/lxc/u1<br>
0.015798 00.056679 cg: adding cgroup /proc/self/fd/23/lxc/u1<br>
0.019688 00.076550 cg: adding cgroup /proc/self/fd/23/lxc/u1<br>
...<br>
and it was 90% of this line.<br>
<br>
Next I calculated the total time spent in this "adding cgroup" stuff<br>
<br>
$ cat dump-rt.log | fgrep 'adding cg' | awk '{t+=$1}END{print t}'<br>
3.12338<br>
<br>
So walking and collecting cgroups for tasks takes ~3.1 out of 3.4+<br>
seconds for the dump.<br>
<br>
-- Pavel<br>
<br>
<br>
> Let's try reducing the verbosity and see what's happening again.<br>
> <br>
> -- Pavel<br>
> <br>
>> Best regards,<br>
>><br>
>><br>
>><br>
>> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------<br>
>> *De :* Pavel Emelyanov <xemul@virtuozzo.com><br>
>> *Envoyé :* mardi 28 février 2017 16:33<br>
>> *À :* Rami Addad; CRIU<br>
>> *Objet :* Re: [CRIU] Technical question<br>
>> <br>
>> On 02/28/2017 07:17 PM, Rami Addad wrote:<br>
>>> Rami Addad a partagé des fichiers OneDrive avec vous. Pour les afficher, cliquez sur les liens ci-dessous.<br>
>>><br>
>>> <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi">https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi</a>><br>
>> <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi">https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi</a>>
<br>
>> statistic.txt <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi">https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi</a>><br>
>> Partagé via OneDrive<br>
>><br>
>><br>
>><br>
>>> <br>
>>> statistic.txt <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi">https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi</a>><br>
>> <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi">https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi</a>>
<br>
>> statistic.txt <<a href="https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi">https://1drv.ms/t/s%21AnSrSEU9SGBag3sDckQPgvLm93bi</a>><br>
>> Partagé via OneDrive<br>
>><br>
>><br>
>><br>
>>> <br>
>>><br>
>>> <<a href="https://1drv.ms/u/s%21AnSrSEU9SGBag3x2OlbNwymfKbOk">https://1drv.ms/u/s%21AnSrSEU9SGBag3x2OlbNwymfKbOk</a>><br>
>>> <br>
>>> dump.sh <<a href="https://1drv.ms/u/s%21AnSrSEU9SGBag3x2OlbNwymfKbOk">https://1drv.ms/u/s%21AnSrSEU9SGBag3x2OlbNwymfKbOk</a>><br>
>>> <br>
>>><br>
>>> Dear all,<br>
>>><br>
>>><br>
>>> for the option --track-mem we put it in every pre-dump and also in the last dump<br>
>>><br>
>>> and you could observe in the statistic.txt file that there are skipped page and also<br>
>>><br>
>>> the freezing time is small and all the others time are small only the frozen time is big<br>
>>><br>
>>><br>
>>><br>
>>> and there is the part of script in file dump.sh <br>
>>><br>
>>><br>
>>><br>
>>> we think that we have took all the possibility but we always have this big time of dump<br>
>><br>
>> OK, here are the stats for final dump<br>
>><br>
>> "dump": {<br>
>> "freezing_time": 8017,<br>
>> "frozen_time": 4243423,<br>
>> "memdump_time": 21419,<br>
>> "memwrite_time": 5866,<br>
>> "pages_scanned": 258539,<br>
>> "pages_skipped_parent": 9985,<br>
>> "pages_written": 1356,<br>
>> "irmap_resolve": 0<br>
>> }<br>
>><br>
>> frozen time is 4 seconds, memdump time is 0.02 seconds, so the time<br>
>> is spent somewhere else.<br>
>><br>
>> First -- try to reduce the verbosity of this final dump, don't use the -vvvvvv<br>
>> option, leave it to be -v0.<br>
>> Second, can you show your dump.log file with increased verbosity, there are<br>
>> timestamps in it, they will help to understand where the time is spent.<br>
>><br>
>> -- Pavel<br>
> <br>
<br>
</div>
</span></font></div>
</div>
</body>
</html>