<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=Windows-1252">
</head>
<body style="font-family: 'Segoe UI',Frutiger,'Frutiger Linotype','Dejavu Sans','Helvetica Neue',Arial,sans-serif; font-size: 14px;">
<div class="hiri-body-wrapper" contenteditable="true">
<div>Hi Sam,<br>
<br>
All of the times reported by Darshan are actually wall times already. There is a subtlety with how the READ/WRITE/META_TIME fields are reported on shared files that is probably causing some confusion, though.<br>
<br>
In this line, for example:<br>
<br>
MPI-IO -1 4647831539574040701 MPIIO_F_WRITE_TIME 471.718718 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/mpiio.dat /lustre/dirac lustre<br>
<br>
The 2nd column is the rank number. If the rank is -1, that means that the file was opened by all ranks, and Darshan has collapsed all of the counters down to a single record representing all ranks.<br>
<br>
The MPIIO_F_WRITE_TIME field represents the (wall) time spent by a rank making MPIIO write calls. So for example, if each rank spent 10 seconds doing this, but you had 8 ranks, then the the total reported in the above line would be 80, not 10, and therefore
might be quite a bit higher than the elapsed run time of the job.<br>
<br>
There are a few options to get around this. You can of course divide the number of ranks back out to get an average per rank for those counters. You can also look at the counters with "SLOWEST" in the name, that retain the timing from the slowest rank even
for shared files. You can also set an environment variable (DARSHAN_DISABLE_SHARED_REDUCTION) to tell darshan *not* to collapse shared files. This might result in a bigger log file (so it's not the default setting), but it will give you distinct accurate
tally for each rank.<br>
<br>
thanks,<br>
-Phil<br>
</div>
</div>
<div class="hiri-extra" contenteditable="false">
<p>On 2019-02-19 11:20:19-05:00 Darshan-users wrote:</p>
<blockquote style="padding-left:10px; border-left:1px solid #ccc; margin:0">
<div>
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style type="text/css"><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
@font-face
{font-family:Menlo;
panose-1:2 11 6 9 3 8 4 2 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
margin-bottom:.0001pt;
font-size:12.0pt;
font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri",sans-serif;
color:windowtext;}
p.p1, li.p1, div.p1
{mso-style-name:p1;
margin:0cm;
margin-bottom:.0001pt;
font-size:7.5pt;
font-family:Menlo;
color:black;}
p.p2, li.p2, div.p2
{mso-style-name:p2;
margin:0cm;
margin-bottom:.0001pt;
font-size:7.5pt;
font-family:Menlo;
color:#B42419;}
span.s2
{mso-style-name:s2;
color:black;}
span.s3
{mso-style-name:s3;
color:#B42419;}
span.s1
{mso-style-name:s1;}
span.apple-converted-space
{mso-style-name:apple-converted-space;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri",sans-serif;}
@page WordSection1
{size:612.0pt 792.0pt;
margin:72.0pt 72.0pt 72.0pt 72.0pt;}
div.WordSection1
{page:WordSection1;}
--></style>
<div class="WordSection1">
<p class="MsoNormal"><span style="font-size:11.0pt">Hi,<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I’m running Darshan 3.1.6. Is there any way to extract the wallclock time of operations from darshan-parser?<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Let’s say I have sample program running on 16 MPI threads: part of it uses serial I/O, and part of it MPI-IO.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="p1"><span class="s1">> time mpirun -np 16 -host localhost ./benchio.x<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I then analyse the results with darshan-parser --total and filter out certain lines:<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="p1"><span class="s1">> /cm/shared/apps/darshan/intel/3.1.6/bin/darshan-parser --total</span><span class="apple-converted-space">
</span><span class="s1">~/dc-cox1_benchio.x_id15025_2-18-43921-17740490755319864674_1.darshan | grep -i "nprocs:\|run time\|POSIX_F_READ_TIME\|POSIX_F_WRITE_TIME\|POSIX_F_META_TIME\|MPIIO_F_READ_TIME\|MPIIO_F_WRITE_TIME\|MPIIO_F_META_TIME"</span><o:p></o:p></p>
<p class="p2"><span class="s2"># </span><span class="s1"><b>nprocs:</b></span><span class="s2"> 16</span><o:p></o:p></p>
<p class="p2"><span class="s2"># </span><span class="s1"><b>run time</b></span><span class="s2">: 83</span><o:p></o:p></p>
<p class="p2"><span class="s2">total_</span><span class="s1"><b>POSIX_F_READ_TIME</b></span><span class="s2">: 0.000000</span><o:p></o:p></p>
<p class="p2"><span class="s2">total_</span><span class="s1"><b>POSIX_F_WRITE_TIME</b></span><span class="s2">: 57.435211</span><o:p></o:p></p>
<p class="p2"><span class="s2">total_</span><span class="s1"><b>POSIX_F_META_TIME</b></span><span class="s2">: 8.595520</span><o:p></o:p></p>
<p class="p2"><span class="s2">total_</span><span class="s1"><b>MPIIO_F_READ_TIME</b></span><span class="s2">: 0.000000</span><o:p></o:p></p>
<p class="p1"><span class="s1">total_</span><span class="s3"><b>MPIIO_F_WRITE_TIME</b></span><span class="s1">: 471.718718</span><o:p></o:p></p>
<p class="p2"><span class="s2">total_</span><span class="s1"><b>MPIIO_F_META_TIME</b></span><span class="s2">: 5.261146</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I also analyse with darshan-parser --base --perf --file-list and filter similarly:<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="p1"><span class="s1">> /cm/shared/apps/darshan/intel/3.1.6/bin/darshan-parser --base --perf --file-list</span><span class="apple-converted-space">
</span><span class="s1">~/dc-cox1_benchio.x_id15025_2-18-43921-17740490755319864674_1.darshan | grep -i "nprocs:\|run time\|POSIX_F_READ_TIME\|POSIX_F_WRITE_TIME\|POSIX_F_META_TIME\|MPIIO_F_READ_TIME\|MPIIO_F_WRITE_TIME\|MPIIO_F_META_TIME"</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">#
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">nprocs:</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 16</span><span style="font-size:7.5pt;font-family:Menlo;color:#B42419"><o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">#
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">run time</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black">: 83</span><span style="font-size:7.5pt;font-family:Menlo;color:#B42419"><o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">POSIX 0 14271214572185876165
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">POSIX_F_READ_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 0.000000 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/serial.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">POSIX 0 14271214572185876165
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">POSIX_F_WRITE_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 39.276790 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/serial.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">POSIX 0 14271214572185876165
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">POSIX_F_META_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 4.394738 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/serial.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">POSIX -1 4647831539574040701
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">POSIX_F_READ_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 0.000000 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/mpiio.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">POSIX -1 4647831539574040701
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">POSIX_F_WRITE_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 18.158421 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/mpiio.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">POSIX -1 4647831539574040701
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">POSIX_F_META_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 4.200782 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/mpiio.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">MPI-IO -1 4647831539574040701
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">MPIIO_F_READ_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 0.000000 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/mpiio.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">MPI-IO -1 4647831539574040701
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">MPIIO_F_WRITE_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 471.718718 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/mpiio.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:7.5pt;font-family:Menlo;color:black">MPI-IO -1 4647831539574040701
</span><b><span style="font-size:7.5pt;font-family:Menlo;color:#B42419">MPIIO_F_META_TIME</span></b><span style="font-size:7.5pt;font-family:Menlo;color:black"> 5.261146 /lustre/dirac/home/dc-cox1/benchio/shared-file/source/benchio_files/mpiio.dat
/lustre/dirac lustre<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Comparing the two outputs, it’s clear that it’s CPU time being measured. But as a high-level profiling aid I’d like to extract the associated wallclock time instead.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I think this would be 39.276+(18.15/16) and 4.39+(4.2/16) for the POSIX_F_WRITE/META_TIME. I’d rather not have to write a separate script to filter against the rank column from the --base --perf --file-list
output.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Thanks in advance,</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Sam<o:p></o:p></span></p>
</div>
</div>
</blockquote>
</div>
</body>
</html>