<div dir="ltr">Oh, this is not hard:<div><br></div><div> /* /\* Put NaN into the time for all events that may not be time accurately since they may happen asynchronously on the GPU *\/ */<br> /* #if defined(PETSC_HAVE_DEVICE) */<br> /* if (!PetscLogGpuTimeFlag && petsc_gflops > 0) { */<br> /* memcpy(&gmaxt,&nas,sizeof(PetscLogDouble)); */<br> /* PetscCall(PetscEventRegLogGetEvent(stageLog->eventLog, name, &eventid)); */<br> /* if (eventid != SNES_Solve && eventid != KSP_Solve && eventid != TS_Step && eventid != TAO_Solve) { */<br> /* memcpy(&mint,&nas,sizeof(PetscLogDouble)); */<br> /* memcpy(&maxt,&nas,sizeof(PetscLogDouble)); */<br> /* } */<br> /* } */<br> /* #endif */<br></div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, May 17, 2022 at 7:17 AM Mark Adams <<a href="mailto:mfadams@lbl.gov">mfadams@lbl.gov</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Can I get some advice on how to add/hack an event now into the reported events?<div><br></div><div>I am noticing that all of the difference in my clean (warmed up) stage comes for KSPSolve:<br><div><br></div><div>KSPSolve 144 1.0 <b>2.1745e+00</b> 1.0 7.50e+10 1.0 0.0e+00 0.0e+00 0.0e+00 42 89 0 0 0 68 98 0 0 0 34511 52718 0 0.00e+00 0 0.00e+00 100<br></div><div>KSPSolve 144 1.0 <b>1.2275e+00</b> 1.0 7.50e+10 1.0 0.0e+00 0.0e+00 0.0e+00 29 89 0 0 0 56 98 0 0 0 61138 <b> -nan</b> 0 0.00e+00 0 0.00e+00 100<br></div></div><div><br></div><div>Maybe it is easier for me to just run it twice and get my Landau numbers from the full report and get KSPSolve numbers from the nan report.</div><div>(Not great for a reproducibility doc)</div><div><br></div><div>Thanks,</div><div>Mark</div><div><br></div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Mon, May 16, 2022 at 10:38 PM Mark Adams <<a href="mailto:mfadams@lbl.gov" target="_blank">mfadams@lbl.gov</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Ok thanks,<div><br><div>And looking at the actual tests that I am doing more carefully I am not seeing much difference in the numbers that I care about with or without the GPU timers.</div><div><br></div></div><div>And FWIW, from a user experience point of view, having -log_view present you with a sea of nans by default is a bit disheartening for a first time user. And they have to send an email and we have to respond ....</div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Mon, May 16, 2022 at 9:36 PM Barry Smith <<a href="mailto:bsmith@petsc.dev" target="_blank">bsmith@petsc.dev</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div><div><br></div> Mark,<div><br></div><div> Yes, Jed has already asked for ways to select certain operations at runtime that would get timed via the GPU timer. I am not sure of the ideal way to handle it. One possibility is PetscLogGpuTimeEvent(event number) which indicates events you want the time logged for. Another is PetscLogGpuTimeObjectID(object ID) which indicates all events for a particular object class would be logged. In either or both cases the PetscLogGPUTime() calls would need to become smarter to determine when they are turned on and off depending on the current state of the logging. Since the events are nested and there can be multiple objects related to the timings I don't have a clear plan in my mind.</div><div><br></div><div> Barry</div><div><br><div><br><blockquote type="cite"><div>On May 16, 2022, at 7:31 PM, Mark Adams <<a href="mailto:mfadams@lbl.gov" target="_blank">mfadams@lbl.gov</a>> wrote:</div><br><div><div dir="ltr">I am not sure I understand the logic, we print the ratio of max/min. <div>I report max and look at the ratio to see if I might be catching some load imbalance or whatever. Is there a problem with that workflow?<div><br></div><div>I assume there is or you would not have done this, so can I add a method that I think also has legitimate values?</div><div><br></div><div>I did observe a 15% hit on my whole stage with the GPU timers but I would still like to take my chances with:</div><div><br></div><div>Landau Operator 29 1.0 1.1200e-02 1.0 4.54e+06 1.0 0.0e+00 0.0e+00 0.0e+00 3 0 0 0 0 40 4 0 0 0 405 509 0 0.00e+00 0 0.00e+00 100<br>Landau Jacobian 15 1.0 7.8189e-03 1.0 4.54e+06 1.0 0.0e+00 0.0e+00 0.0e+00 2 0 0 0 0 28 4 0 0 0 580 731 0 0.00e+00 0 0.00e+00 100<br>Landau Mass 14 1.0 3.3759e-03 1.0 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 1 0 0 0 0 12 0 0 0 0 0 0 0 0.00e+00 0 0.00e+00 0<br></div><div><br></div><div>These methods require barriers at the end before they call MatSetValuesCOO, which is like < 1% of these total matrix times, so I trust the data w/o GPU times set.</div><div><br></div><div>(The rest of the stage is the rest of the time step, which is mostly the linear solver, and I guess that is where the 15% comes from but I have not dug into it)</div><div><br></div><div>Thanks,</div><div>Mark</div><div><br></div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, Apr 27, 2022 at 11:06 AM Barry Smith <<a href="mailto:bsmith@petsc.dev" target="_blank">bsmith@petsc.dev</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div><div><br></div> Only KSPSolve, SNESSolve, TSSolve will have legitimate values. "High-level" functions like PtAP can be asynchronous (meaning the GPU returns to the CPU to do more stuff) before they are complete, hence their timings would be incorrect and so they must be labeled with a special marker and not have numbers for time.<div><br></div><div> Jed reports a possible 10% smaller time for KSPSolve() in this mode in some of his runs, compared to timing correctly the inner operations, and thus feels it is the best default.</div><div><br></div><div> Barry</div><div><br><div><br><blockquote type="cite"><div>On Apr 27, 2022, at 10:08 AM, Mark Adams <<a href="mailto:mfadams@lbl.gov" target="_blank">mfadams@lbl.gov</a>> wrote:</div><br><div><div dir="ltr"><div dir="ltr"><br></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, Apr 26, 2022 at 8:00 PM Barry Smith <<a href="mailto:bsmith@petsc.dev" target="_blank">bsmith@petsc.dev</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div><div><br></div> The current nan output has to be replaced to get the column alignment correct, I just didn't feel like making that change also in the same MR. <div><br></div><div> Something like Unknown or anything that fits in the column space would be fine. It just means for the given run the timing numbers are not meaningful/correct for those events. </div></div></blockquote><div><br></div><div>Just a note, just about every event is NAN for me. My GAMG setup that is all CPU is NAN. High level functions like PtAP as well. </div><div>That said, adding <span style="color:rgb(85,85,85);letter-spacing:0.2px;white-space:nowrap">-log_view_gpu_time is fine. Not worth the churn.</span></div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div><div>This is to obtain the best meaningful results for the outer events per Jed since timing the inner events accurately introduces extra time in the outer events. That is it is not possible to have the best accurate times for both inner events and outer events in the same run. So if you want to compare KSPSolve timings, for example, you run as-is, it you want to examine, low-level vector operations run also with -log_view_gpu_time but know that the KSP times are higher than need be.</div><div><br></div><div> Sorry for the confusion.</div><div><br></div><div><br><br><div><br><blockquote type="cite"><div>On Apr 26, 2022, at 3:49 PM, Matthew Knepley <<a href="mailto:knepley@gmail.com" target="_blank">knepley@gmail.com</a>> wrote:</div><br><div><div dir="ltr"><div dir="ltr">On Tue, Apr 26, 2022 at 12:03 PM Mark Adams <<a href="mailto:mfadams@lbl.gov" target="_blank">mfadams@lbl.gov</a>> wrote:<br></div><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Well, Nans are a clear sign that something is very wrong.</div></blockquote><div><br></div><div>Barry chose them so that it could not be mistaken for an actual number.</div><div><br></div><div> Matt</div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, Apr 26, 2022 at 11:52 AM Jacob Faibussowitsch <<a href="mailto:jacob.fai@gmail.com" target="_blank">jacob.fai@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">There is an automatic warning that shows when you do run with `-log_view_gpu_time`, but perhaps there should also be an automatic warning when *not* running with it. It is unfortunate that NaN is the value printed as this implies a bug but AFAIK it is unavoidable (Barry can say more on this though).<br>
<br>
Best regards,<br>
<br>
Jacob Faibussowitsch<br>
(Jacob Fai - booss - oh - vitch)<br>
<br>
> On Apr 26, 2022, at 09:48, Jose E. Roman <<a href="mailto:jroman@dsic.upv.es" target="_blank">jroman@dsic.upv.es</a>> wrote:<br>
> <br>
> You have to add -log_view_gpu_time<br>
> See <a href="https://gitlab.com/petsc/petsc/-/merge_requests/5056" rel="noreferrer" target="_blank">https://gitlab.com/petsc/petsc/-/merge_requests/5056</a><br>
> <br>
> Jose<br>
> <br>
> <br>
>> El 26 abr 2022, a las 16:39, Mark Adams <<a href="mailto:mfadams@lbl.gov" target="_blank">mfadams@lbl.gov</a>> escribió:<br>
>> <br>
>> I'm seeing this on Perlmutter with Kokkos-CUDA. Nans in most log timing data except the two 'Solve' lines.<br>
>> Just cg/jacobi on snes/ex56.<br>
>> <br>
>> Any ideas?<br>
>> <br>
>> VecTDot 2 1.0 nan nan 1.20e+01 1.0 0.0e+00 0.0e+00 0.0e+00 0 0 0 0 0 0 0 0 0 0 -nan -nan 0 0.00e+00 0 0.00e+00 100<br>
>> VecNorm 2 1.0 nan nan 1.00e+01 1.0 0.0e+00 0.0e+00 0.0e+00 0 0 0 0 0 0 0 0 0 0 -nan -nan 0 0.00e+00 0 0.00e+00 100<br>
>> VecCopy 2 1.0 nan nan 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 0 0 0 0 0 0 0 0 0 0 -nan -nan 0 0.00e+00 0 0.00e+00 0<br>
>> VecSet 5 1.0 nan nan 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 0 0 0 0 0 0 0 0 0 0 -nan -nan 0 0.00e+00 0 0.00e+00 0<br>
>> VecAXPY 4 1.0 nan nan 2.40e+01 1.0 0.0e+00 0.0e+00 0.0e+00 0 0 0 0 0 1 0 0 0 0 -nan -nan 0 0.00e+00 0 0.00e+00 100<br>
>> VecPointwiseMult 1 1.0 nan nan 3.00e+00 1.0 0.0e+00 0.0e+00 0.0e+00 0 0 0 0 0 0 0 0 0 0 -nan -nan 0 0.00e+00 0 0.00e+00 100<br>
>> KSPSetUp 1 1.0 nan nan 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 0 0 0 0 0 0 0 0 0 0 -nan -nan 0 0.00e+00 0 0.00e+00 0<br>
>> KSPSolve 1 1.0 4.0514e-04 1.0 5.50e+01 1.0 0.0e+00 0.0e+00 0.0e+00 1 0 0 0 0 2 0 0 0 0 0 -nan 0 0.00e+00 0 0.00e+00 100<br>
>> SNESSolve 1 1.0 2.2128e-02 1.0 5.55e+05 1.0 0.0e+00 0.0e+00 0.0e+00 72 56 0 0 0 100100 0 0 0 25 -nan 0 0.00e+00 0 0.00e+00 0<br>
> <br>
<br>
</blockquote></div>
</blockquote></div><br clear="all"><div><br></div>-- <br><div dir="ltr"><div dir="ltr"><div><div dir="ltr"><div><div dir="ltr"><div>What most experimenters take for granted before they begin their experiments is infinitely more interesting than any results to which their experiments lead.<br>-- Norbert Wiener</div><div><br></div><div><a href="http://www.cse.buffalo.edu/~knepley/" target="_blank">https://www.cse.buffalo.edu/~knepley/</a><br></div></div></div></div></div></div></div></div>
</div></blockquote></div><br></div></div></blockquote></div></div>
</div></blockquote></div><br></div></div></blockquote></div>
</div></blockquote></div><br></div></div></blockquote></div>
</blockquote></div>
</blockquote></div>