added event and summary log options, and using only clhep, g4 includes in gemc_dep

Author: maureeungaro

gemc.cc

@@ -20,11 +20,17 @@
 #include "gfield_options.h"
 
 // c++
-#include <cstdio>
+#include <chrono>
 #include <cstdlib>
+#if defined(__linux__)
+#include <cstdio> // IWYU pragma: keep -- std::fflush on the Linux fast-exit path in main()
+#endif
 
 int main(int argc, char* argv[]) {
 
+	// Anchor for the optional -print_summary timing report (total wall-clock time).
+	const auto program_start = std::chrono::steady_clock::now();
+
 	auto base_schema = gemc::defineOptions();
 	base_schema += gemc::collectPluginOptions(argc, argv);
 	auto gopts = std::make_shared<GOptions>(argc, argv, base_schema);
@@ -150,6 +156,23 @@ int main(int argc, char* argv[]) {
 		delete session;
 	}
 
+	// print_summary is a switch, on by default; disable with -print_summary=false.
+	if (gopts->getSwitch("print_summary")) {
+		const auto   now     = std::chrono::steady_clock::now();
+		const double total_s = std::chrono::duration<double>(now - program_start).count();
+		log->info(0, "Timing summary: total simulation time ", total_s, " seconds.");
+		if (geventDispenser->beamOnIssued()) {
+			const double beam_s     = std::chrono::duration<double>(now - geventDispenser->beamOnStartTime()).count();
+			const int    total_n    = geventDispenser->getTotalNumberOfEvents();
+			log->info(0, "Timing summary: total time since beamOn was issued ", beam_s, " seconds.");
+			if (beam_s > 0.0) {
+				const double avg_rate = static_cast<double>(total_n) / beam_s;
+				log->info(0, "Timing summary: average event rate ", avg_rate, " events / second (",
+				          total_n, " events / ", beam_s, " seconds).");
+			}
+		}
+	}
+
 	geventDispenser.reset();
 	preloaded_gstreamer_map.reset();
 	runManager.reset();

gemc/actions/event/gEventAction.cc

@@ -5,13 +5,17 @@
 #include "G4Event.hh"
 #include "G4Threading.hh"
 
+// c++
+#include <string>
+
 // gemc
 #include "event/gEventDataCollection.h"
 #include "../generator/gPrimaryGeneratorAction.h"
 
 // c++
 #include <algorithm>
 #include <cctype>
+#include <chrono>
 
 namespace {
 GGeneratedParticleBank make_generated_particle_bank(const GParticleRecordEvent& particles) {
@@ -42,6 +46,18 @@ bool scalar_bool_option_enabled(const std::shared_ptr<GOptions>& goptions, const
 	               [](unsigned char c) { return static_cast<char>(std::tolower(c)); });
 	return value == "true" || value == "1" || value == "yes" || value == "on";
 }
+
+// Convert a substring to a non-negative integer, returning false on any malformed input.
+bool to_non_negative_int(const std::string& text, int& out) {
+	if (text.empty()) return false;
+	size_t pos = 0;
+	int    value;
+	try { value = std::stoi(text, &pos); }
+	catch (...) { return false; }
+	if (pos != text.size() || value < 0) return false;
+	out = value;
+	return true;
+}
 }
 
 
@@ -51,8 +67,65 @@ GEventAction::GEventAction(const std::shared_ptr<GOptions>& gopt, GRunAction* ru
 	GBase(gopt, EVENTACTION_LOGGER),
 	goptions(gopt),
 	run_action(run_a) {
-	const auto desc = "GEventAction " + std::to_string(G4Threading::G4GetThreadId());
+	const auto thread_id = G4Threading::G4GetThreadId();
+	const auto desc      = "GEventAction " + std::to_string(thread_id);
 	log->debug(CONSTRUCTOR, FUNCTION_NAME, desc);
+
+	// Parse the log_every option of the form N or N-NTH. Anything malformed disables the
+	// feature and is reported once (from thread 0) to avoid duplicated warnings across workers.
+	std::string spec = goptions->getScalarString(LOG_EVERY_OPTION);
+	if (!spec.empty() && spec != UNINITIALIZEDSTRINGQUANTITY) {
+		const auto dash = spec.find('-');
+		std::string n_part   = dash == std::string::npos ? spec : spec.substr(0, dash);
+		std::string nth_part = dash == std::string::npos ? std::string() : spec.substr(dash + 1);
+
+		// Effective worker-thread count, mirroring gemc::get_nthreads clamping (0 means all cores).
+		int nthreads = goptions->getScalarInt("nthreads");
+		const int ncores = G4Threading::G4GetNumberOfCores();
+		if (nthreads == 0 || nthreads > ncores) nthreads = ncores;
+
+		int n = 0;
+		if (!to_non_negative_int(n_part, n) || n == 0) {
+			if (thread_id <= 0)
+				log->warning("Ignoring invalid -", LOG_EVERY_OPTION, "=", spec,
+				             " : N must be a positive integer.");
+		}
+		else if (dash != std::string::npos) {
+			int nth = 0;
+			if (!to_non_negative_int(nth_part, nth) || nth >= nthreads) {
+				if (thread_id <= 0)
+					log->warning("Ignoring invalid -", LOG_EVERY_OPTION, "=", spec,
+					             " : thread id must be in [0, ", nthreads - 1, "].");
+			}
+			else {
+				log_every_n      = n;
+				log_every_thread = nth;
+			}
+		}
+		else { log_every_n = n; }
+	}
+}
+
+// Print the periodic "Starting event" line, honoring the log module and optional thread filter.
+// The reported event number, count and rate are all per worker thread: each enabled thread logs
+// every N events it processes, showing its own 1-based event count and average rate (events / second).
+void GEventAction::log_event_start(int thread_id) {
+	if (log_every_n <= 0) return;
+	if (log_every_thread >= 0 && log_every_thread != thread_id) return;
+
+	// Anchor this thread's clock on its first counted event, then count this event.
+	const auto now = std::chrono::steady_clock::now();
+	if (log_events_seen == 0) { log_start_time = now; }
+	++log_events_seen;
+
+	if (log_events_seen % log_every_n != 0) return;
+
+	const double elapsed_s = std::chrono::duration<double>(now - log_start_time).count();
+	const double rate      = elapsed_s > 0.0 ? static_cast<double>(log_events_seen) / elapsed_s : 0.0;
+
+	// log_events_seen is this thread's own 1-based count, not the global Geant4 event id.
+	log->info(0, "Starting event n. ", log_events_seen, " in thread ", thread_id,
+	          ". Average rate: ", rate, " events / second");
 }
 
 // Begin-of-event hook used mainly for tracing event and thread identifiers.
@@ -61,6 +134,8 @@ void GEventAction::BeginOfEventAction([[maybe_unused]] const G4Event* event) {
 	const auto event_id  = event->GetEventID();
 
 	log->debug(NORMAL, FUNCTION_NAME, " event id ", event_id, " in thread ", thread_id);
+
+	log_event_start(thread_id);
 }
 
 // Finalize the event by reading hit collections, digitizing them, routing the

gemc/actions/event/gEventAction.h

@@ -7,6 +7,9 @@
 #include <gemc/gbase/gbase.h>
 #include <gemc/actions/run/gRunAction.h>
 
+// c++
+#include <chrono>
+
 /**
  * \file gEventAction.h
  * \brief Declares GEventAction, the per-event processing action for the GEMC actions module.
@@ -16,6 +19,16 @@
 
 constexpr const char* EVENTACTION_LOGGER = "geventaction";
 
+/**
+ * \brief Name of the option controlling periodic per-event log messages.
+ *
+ * Accepts a string of the form \c N or \c N-NTH (N is the log module):
+ * - \c N    : every worker thread prints a message each time it has processed a multiple of N
+ *             events (the count is per thread, not the global event id).
+ * - \c N-NTH: as above, but only the worker thread with id NTH prints (0 <= NTH < nthreads).
+ */
+constexpr const char* LOG_EVERY_OPTION = "log_every";
+
 /**
  * \brief Namespace containing helpers related to event-action configuration.
  *
@@ -27,7 +40,35 @@ namespace geventaction {
 	 *
 	 * \return A GOptions object scoped to the event-action logger name.
 	 */
-	inline GOptions defineOptions() { return GOptions(EVENTACTION_LOGGER); }
+	inline GOptions defineOptions() {
+		GOptions goptions(EVENTACTION_LOGGER);
+
+		std::string help = "Print a progress log line every N events, with the average event rate.\n \n";
+		help += GTAB;
+		help += "The value is a string of the form N or N-NTH, where N is the log module:\n";
+		help += GTABTAB;
+		help += "N     : every worker thread prints 'Starting event n. <k> in thread <tid>.\n";
+		help += GTABTABTAB;
+		help += "Average rate: <r> events / second' every time it has processed a multiple\n";
+		help += GTABTABTAB;
+		help += "of N events. <k> is that thread's own 1-based event count (not the global\n";
+		help += GTABTABTAB;
+		help += "Geant4 event id), and <r> is that thread's average rate.\n";
+		help += GTABTAB;
+		help += "N-NTH : as above, but only the worker thread with id NTH prints. NTH must be\n";
+		help += GTABTABTAB;
+		help += "in the range [0, nthreads-1].\n \n";
+		help += GTAB;
+		help += "Examples: -log_every=100 (all threads, every 100 events)\n";
+		help += GTABTAB;
+		help += "-log_every=100-2 (only thread 2, every 100 events)\n";
+		goptions.defineOption(
+			GVariable(LOG_EVERY_OPTION, UNINITIALIZEDSTRINGQUANTITY,
+			          "log module: print event progress and average rate every N events per thread"),
+			help);
+
+		return goptions;
+	}
 } // namespace geventaction
 
 
@@ -108,11 +149,45 @@ class GEventAction : public GBase<GEventAction>, public G4UserEventAction
 	 */
 	void publish_event_data(const std::shared_ptr<GEventDataCollection>& event_data) const;
 
+	/**
+	 * \brief Emits the periodic "Starting event" log line when enabled and due.
+	 *
+	 * Honors the \c log_every option: prints only when the log module is configured (> 0)
+	 * and (when a thread filter is set) the running thread matches the requested one. The
+	 * count is kept per worker thread, so the line is printed every time this thread has
+	 * processed a multiple of N events. The reported event number is this thread's own
+	 * 1-based count (not the global Geant4 event id), along with this thread's average rate
+	 * (events / second) since its first counted event.
+	 *
+	 * \param thread_id Id of the worker thread processing the event.
+	 */
+	void log_event_start(int thread_id);
+
+	/**
+	 * \brief Number of events processed by this worker thread while logging is enabled.
+	 */
+	long long log_events_seen = 0;
+
+	/**
+	 * \brief Steady-clock anchor set on this thread's first counted event.
+	 */
+	std::chrono::steady_clock::time_point log_start_time;
+
 	/**
 	 * \brief Shared configuration used to build event products and control logging.
 	 */
 	std::shared_ptr<GOptions> goptions;
 
+	/**
+	 * \brief Event-id modulo for periodic logging; 0 disables the feature.
+	 */
+	int log_every_n = 0;
+
+	/**
+	 * \brief Worker-thread id allowed to log, or -1 to allow all threads.
+	 */
+	int log_every_thread = -1;
+
 	/**
 	 * \brief Non-owning pointer to the thread-local run action associated with this event action.
 	 *

gemc/eventDispenser/eventDispenser.cc

@@ -200,6 +200,8 @@ int EventDispenser::processEvents() {
 		// The command string is a standard Geant4 UI command: \c /run/beamOn <N>.
 		log->info(1, "Processing ", nevents, " events in one go");
 		closeOpenGeometryBeforeBeamOn(log);
+		// Record the moment the first BeamOn is issued so a timing summary can be produced later.
+		if (!beamOnTime.has_value()) { beamOnTime = std::chrono::steady_clock::now(); }
 		g4uim->ApplyCommand("/run/beamOn " + to_string(nevents));
 		// Take the screenshot after BeamOn returns. At this point G4VisManager::EndOfRun()
 		// has already joined the vis subthread (ARM64 offset 0xa35f8: bl thread::join), so

gemc/eventDispenser/eventDispenser.h

@@ -3,8 +3,10 @@
 #include <gemc/gbase/gbase.h>
 #include <gemc/gdynamicDigitization/gdynamicdigitization.h>
 
+#include <chrono>
 #include <map>
 #include <memory>
+#include <optional>
 #include <vector>
 
 /**
@@ -85,6 +87,9 @@ class EventDispenser : public GBase<EventDispenser>
 	/// Index into \ref listOfRuns used by \ref getCurrentRun "getCurrentRun()".
 	int currentRunIndex{};
 
+	/// Wall-clock time when the first \c /run/beamOn was issued; unset until then.
+	std::optional<std::chrono::steady_clock::time_point> beamOnTime;
+
 	/** @} */
 
 	/**
@@ -174,6 +179,22 @@ class EventDispenser : public GBase<EventDispenser>
 	 */
 	int processEvents();
 
+	/**
+	 * \brief Returns whether at least one \c /run/beamOn has been issued.
+	 *
+	 * \return True once \ref processEvents() has dispatched its first run.
+	 */
+	[[nodiscard]] bool beamOnIssued() const { return beamOnTime.has_value(); }
+
+	/**
+	 * \brief Returns the wall-clock time of the first \c /run/beamOn.
+	 *
+	 * \warning Only meaningful when \ref beamOnIssued() returns true.
+	 *
+	 * \return Steady-clock time point captured just before the first BeamOn command.
+	 */
+	[[nodiscard]] std::chrono::steady_clock::time_point beamOnStartTime() const { return beamOnTime.value(); }
+
 	/**
 	 * \brief Sets the total number of events to process in single-run mode.
 	 *

gemc/goptions/goptions.cc

@@ -20,13 +20,28 @@
 #include "gutilities.h"
 
 // c++
+#include <algorithm>
 #include <iostream>
 #include <cstring>
 #include <cctype>
 #include <cstdlib>
 
 using namespace std;
 
+namespace {
+// Parse a human-friendly boolean token used for switches (-switch=value and YAML switch values).
+// Accepts, case-insensitively: true/1/yes/y/on and false/0/no/n/off. Returns false if @p raw is
+// not a recognized token, leaving @p out untouched.
+bool parse_bool_token(const std::string& raw, bool& out) {
+	std::string v = raw;
+	std::transform(v.begin(), v.end(), v.begin(),
+	               [](unsigned char c) { return static_cast<char>(std::tolower(c)); });
+	if (v == "true" || v == "1" || v == "yes" || v == "y" || v == "on") { out = true; return true; }
+	if (v == "false" || v == "0" || v == "no" || v == "n" || v == "off") { out = false; return true; }
+	return false;
+}
+}
+
 // See goptions.h for full constructor API documentation.
 /*
  * Parsing precedence implemented here:
@@ -155,10 +170,10 @@ GOptions::GOptions(int argc, char* argv[], const GOptions& user_defined_options)
 				// Switch with an explicit boolean value: -gui=false / -gui=true. This gives the
 				// CLI a way to turn a switch off, honoring the documented CLI-over-YAML precedence.
 				if (switches.find(keyPart) != switches.end()) {
-					if (valuePart == "true" || valuePart == "1") { switches[keyPart].turnOn(); }
-					else if (valuePart == "false" || valuePart == "0") { switches[keyPart].turnOff(); }
+					bool on = false;
+					if (parse_bool_token(valuePart, on)) { on ? switches[keyPart].turnOn() : switches[keyPart].turnOff(); }
 					else {
-						cerr << "The switch " << keyPart << " accepts only true/false." << endl;
+						cerr << "The switch " << keyPart << " accepts only true/false/yes/no/on/off/1/0." << endl;
 						exit(EC__NOOPTIONFOUND);
 					}
 					continue;
@@ -224,9 +239,9 @@ GOptions::GOptions(int argc, char* argv[], const GOptions& user_defined_options)
 }
 
 // Implementation note: public API docs are in goptions.h (avoid duplicate \param blocks).
-void GOptions::defineSwitch(const std::string& name, const std::string& description) {
+void GOptions::defineSwitch(const std::string& name, const std::string& description, bool default_status) {
 	if (switches.find(name) == switches.end()) {
-		switches[name] = GSwitch(description);
+		switches[name] = GSwitch(description, default_status);
 	}
 	else {
 		std::cerr << FATALERRORL << "The " << YELLOWHHL << name << RSTHHR
@@ -409,7 +424,15 @@ void GOptions::setOptionsValuesFromYamlFile(const std::string& yaml) {
 				exit(EC__NOOPTIONFOUND);
 			}
 			else {
-				switches[option_name].turnOn();
+				// A bare key (null value) means "present" -> on; an explicit boolean value is honored,
+				// so a default-on switch can be turned off from YAML (e.g. print_summary: false).
+				bool on = true;
+				if (it->second.IsScalar() && !parse_bool_token(it->second.as<std::string>(), on)) {
+					cerr << FATALERRORL << "The switch " << YELLOWHHL << option_name << RSTHHR
+						<< " accepts only true/false/yes/no/on/off/1/0." << endl;
+					exit(EC__NOOPTIONFOUND);
+				}
+				on ? switches[option_name].turnOn() : switches[option_name].turnOff();
 			}
 		}
 		else {