Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Time tracing for the openPMD plugin #4909

Conversation

franzpoeschel
Copy link
Contributor

@franzpoeschel franzpoeschel commented May 23, 2024

This is something that I've been using for years now on a private branch of PIConGPU, but having an approachable way to get detailed timing information from the openPMD plugin is probably not only relevant for me.

This is disabled by default (via a no-op template specialization), but can be enabled in CMake via -DPIC_IO_TIMES_NUMBER_OF_FILES. The value of this parameter is an integer that specifies how many MPI ranks should participate in this time tracing. Every MPI rank writes its own output file with timing information, and at large scale only a subselection of MPI ranks should do that in order not to accidentally destroy the performance while trying to measure it.

The output for one run of the plugin may look sth like this:

1716472984082   2624    Beginning iteration 50
1716472984135   53      Begin write field E: 25165824 bytes for 2097152 cells 
1716472984135   0               Component 0 prepare
1716472984140   5               Component 0 flush
1716472984153   12              Component 0 end
1716472984153   0               Component 1 prepare
1716472984159   5               Component 1 flush
1716472984171   12              Component 1 end
1716472984171   0               Component 2 prepare
1716472984176   5               Component 2 flush
1716472984189   12              Component 2 end
1716472984192   2       Begin write field B: 25165824 bytes for 2097152 cells 
1716472984192   0               Component 0 prepare
1716472984197   5               Component 0 flush
1716472984209   12              Component 0 end
1716472984209   0               Component 1 prepare
1716472984215   5               Component 1 flush
1716472984227   12              Component 1 end
1716472984227   0               Component 2 prepare
1716472984232   5               Component 2 flush
1716472984244   12              Component 2 end
1716472984244   0       Begin write field e_all_chargeDensity: 8388608 bytes for 2097152 cells
1716472984248   3               Component 0 prepare
1716472984253   4               Component 0 flush
1716472984265   12              Component 0 end
1716472984265   0       Begin write field e_all_energyDensity: 8388608 bytes for 2097152 cells
1716472984268   3               Component 0 prepare
1716472984273   4               Component 0 flush
1716472984285   12              Component 0 end
1716472984285   0       Begin write species e
1716472984315   29              slice 0 prepare: 52428800 bytes for 1310720 particles from offset 0
1716472984346   31              slice 0 flush
1716472984423   76              slice 0 end
1716472984434   11              slice 1 prepare: 52428800 bytes for 1310720 particles from offset 1310720
1716472984465   30              slice 1 flush
1716472984543   78              slice 1 end
1716472984543   0               slice 2 prepare: 0 bytes for 0 particles from offset 2621440
1716472984543   0               slice 2 flush
1716472984676   132             slice 2 end
1716472984676   0               slice 3 prepare: 0 bytes for 0 particles from offset 2621440
1716472984676   0               slice 3 flush
1716472984700   24              slice 3 end
1716472984703   3               Flush species e
1716472984704   0               Finished flush species
1716472984704   0       Closing iteration 50
1716472984840   136     Done.

The first column is the UNIX time stamp, the second column the diff time in milliseconds to the previous event, the rest is description.

Copy link
Contributor Author

@franzpoeschel franzpoeschel left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some todos for myself

include/picongpu/CMakeLists.txt Outdated Show resolved Hide resolved
include/picongpu/plugins/openPMD/DumpTimes.hpp Outdated Show resolved Hide resolved
include/picongpu/plugins/openPMD/DumpTimes.hpp Outdated Show resolved Hide resolved
include/picongpu/plugins/openPMD/openPMDWriter.def Outdated Show resolved Hide resolved
include/picongpu/plugins/openPMD/DumpTimes.hpp Outdated Show resolved Hide resolved
@psychocoderHPC psychocoderHPC added the component: plugin in PIConGPU plugin label May 27, 2024
include/picongpu/CMakeLists.txt Outdated Show resolved Hide resolved
include/picongpu/CMakeLists.txt Outdated Show resolved Hide resolved
@@ -102,6 +103,50 @@ namespace picongpu
DataSpace<simDim> localWindowToDomainOffset;

std::vector<double> times;
static constexpr bool do_trace_times = PIC_IO_TIMES_NUMBER_OF_FILES > 0;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe timeTraceEnabled

note: we use camel case for variables in PIConGPU

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've used enableTimeTrace now

include/picongpu/plugins/openPMD/openPMDWriter.def Outdated Show resolved Hide resolved
include/picongpu/plugins/openPMD/openPMDWriter.def Outdated Show resolved Hide resolved
std::chrono::duration_cast<std::chrono::milliseconds>(currentTime.time_since_epoch()).count());
}
};
template<typename Clock>
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

= std::chrono::milliseconds then we can remove it from a bunch of code but it still allows us to change the precision.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've restructured this to:

        template<bool enable = true, typename Clock = std::chrono::system_clock>
        class DumpTimes
        {
        public:

            // ...

            using TimeFormatter = typename TimeFormatters<Clock>::TimeFormatter;

@psychocoderHPC psychocoderHPC added this to the 0.8.0 / Next stable milestone May 27, 2024
@psychocoderHPC psychocoderHPC added the changelog PR's marked with this label will be added to the changelog label May 31, 2024
@psychocoderHPC psychocoderHPC merged commit fb51b2e into ComputationalRadiationPhysics:dev May 31, 2024
9 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
changelog PR's marked with this label will be added to the changelog component: plugin in PIConGPU plugin
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants