Re: [Libmesh-users] App spends lots of time in _eq.reinit()

[Roy S. <roy...@ic...>]

On Thu, 19 Oct 2017, Jesse Carter wrote:

> On Thu, Oct 19, 2017 at 10:38 AM, Roy Stogner <roy...@ic...> wrote:
>
>       I'll look through it soon, at least to see if there's any low-hanging
>       fruit.

One bit of embarrassing low-hanging fruit that I often forget: when
*really* benchmarking, remember that our libMesh::PerfLog has a bit of
a heisenbug: it does string manipulation to an extent that invalidates
its own results if we try to use it too fine-grained.

For example:

$ time ../../PRARIEDOG-opt -i 2d_sink_map_with_refinement.i UserObjects/terminator/expression="num_past_events>=20" Mesh/nx=20 Mesh/ny=20 Mesh/nz=20 Outputs/exodus=false --disable-perflog | tail -3
real    1m1.863s
user    1m0.642s
sys     0m0.136s

$ time ../../PRARIEDOG-opt -i 2d_sink_map_with_refinement.i UserObjects/terminator/expression="num_past_events>=20" Mesh/nx=20 Mesh/ny=20 Mesh/nz=20 Outputs/exodus=false | tail -3
real    1m51.894s
user    1m50.719s
sys     0m0.115s

That's actually pretty damning... it does take us less than a
microsecond to do each logging event, but since our logging is so fine
grained that it can run a hundred million times on a small problem,
that's not insignificant!  I had no idea it was so bad!  And I even
made it about 30% *worse* while I was working on the projection
refactoring, because I added more fine-grained logging there and
didn't remove it afterwards.

I know this is kind of a red herring, since "--disable-perflog" works
just fine, but I think I'm going to quickly see if I can get the
string allocation/deallocation out of our PerfLog operations, and if
doing so makes them cheap enough to leave enabled by default.
Otherwise we still need to do *something*, whether turning off the
finer grained logging, or even turning off logging by default in opt
mode, because "hope our performance-concerned users know to specify
--ironically-ignore-performance on the command line" is not a good
attitude...
---
Roy