GCC Code Coverage Report

Line	Branch	Exec	Source
1			#include "na64dp/processingInfo.hh"
2			#include "na64util/str-fmt.hh"
3			#include "na64util/log4cpp-extras.hh"
4			#include "na64dp/abstractHitHandler.hh"
5
6			#include <cassert>
7			#include <ctime>
8			#include <iomanip>
9			#include <sstream>
10
11			namespace na64dp {
12
13			//
14			// Basic registry
15
16			void
17		✗	iEvStatProcInfo::register_handler( const AbstractHandler * hPtr
18			, const std::string & hName ) {
19		✗	auto ir = emplace( hPtr, aux::HandlerStatisticsEntry( hName ) );
20		✗	assert(ir.second);
21		✗	ir.first->second.handlerPtr = hPtr;
22		✗	ir.first->second.hitHandlerPtr = dynamic_cast<const HitHandlerStats *>(hPtr);
23		✗	_ordered.push_back( &stats_for(hPtr) );
24			}
25
26			aux::HandlerStatisticsEntry &
27		✗	iEvStatProcInfo::stats_for( const AbstractHandler * hPtr ) {
28		✗	auto it = find(hPtr);
29		✗	if( end() == it ) {
30		✗	NA64DP_RUNTIME_ERROR( "Can not find registered handler by given pointer." );
31			}
32		✗	return it->second;
33			}
34
35			void
36		✗	iEvStatProcInfo::notify_event_read() {
37		✗	if(!_started) { _started = clock(); }
38		✗	++_nEvsProcessed;
39			//return _nEvsToProcess > 0 ? _nEvsProcessed < _nEvsToProcess : true;
40			}
41
42			void
43		✗	iEvStatProcInfo::notify_event_discriminated( const AbstractHandler * hPtr ) {
44		✗	++stats_for(hPtr).nDiscriminated;
45			}
46
47			void
48		✗	iEvStatProcInfo::notify_handler_starts( const AbstractHandler * hPtr ) {
49		✗	stats_for(hPtr)._started = clock();
50			}
51
52			void
53		✗	iEvStatProcInfo::notify_handler_done( const AbstractHandler * hPtr ) {
54		✗	auto & s = stats_for(hPtr);
55		✗	s.elapsed += clock() - s._started;
56			}
57
58			size_t
59		✗	iEvStatProcInfo::n_events_discriminated() const {
60		✗	size_t n = 0;
61		✗	for(auto const hsp : _ordered) {
62		✗	n += hsp->nDiscriminated;
63			}
64		✗	return n;
65			}
66
67			void
68		✗	iEvStatProcInfo::finalize() {
69		✗	assert(_ended == 0);
70		✗	_ended = clock();
71			}
72
73			clock_t
74		✗	iEvStatProcInfo::elapsed() const {
75		✗	if(0 == _started) return 0.;
76		✗	if(_ended) return _ended - _started;
77		✗	return clock() - _started;
78			}
79
80			// Helper function producing output:
81			// - 604800 abs secs is "168h 0m 0.000s"
82			// 123456789|1234
83			// - 3 abs secs is "3.000s"
84			// - 75 abs secs is "1m 15.000s"
85			size_t
86		✗	abs_sec_to_hr(clock_t nSecAbs, char * strBuf, size_t bufLen) {
87			unsigned int nHours, nMins;
88		✗	double nSec_ = static_cast<double>(nSecAbs)/CLOCKS_PER_SEC;
89		✗	nHours = static_cast<unsigned int>(nSec_/3600);
90		✗	nSec_ -= 3600*nHours;
91		✗	nMins = static_cast<unsigned int>(nSec_/60);
92		✗	nSec_ -= 60*nMins;
93		✗	if(0 != nHours) {
94		✗	return snprintf(strBuf, bufLen, "%uh %um %02.2fs", nHours, nMins, nSec_);
95		✗	} else if(0 != nMins) {
96		✗	return snprintf(strBuf, bufLen, "%um %02.2fs", nMins, nSec_);
97			} else {
98		✗	if(nSec_ >= 5e-2) {
99		✗	return snprintf(strBuf, bufLen, "%02.2fs", nSec_);
100		✗	} else if(nSec_ > 5e-4) {
101		✗	return snprintf(strBuf, bufLen, "%.2fms", nSec_*1e3);
102			} else {
103		✗	return snprintf(strBuf, bufLen, "%.2fus", nSec_*1e6);
104			}
105			}
106			}
107
108			#if 0
109			Overall summary:
110			Time elapsed ........... 1h 3m 45.3s (1.23 ev/s)
111			Events considered ...... 123478
112			Events discriminated ... 345 (23%)
113			Handlers summary:
114			#. LABEL ELAPSED DISCRIMINATED
115			1. Plot something ................ 0.3s ...... 0, 100.2%
116			2. Discriminate RC ....... 12h 5m 23.1s ... 2345, 36.3%
117			3. Subpipe: consider foo ......... 0.7s ..... 22, 34.5%
118			3.1 Discriminate one ............. 0.4s ... [11], [16.25%]
119			3.2 Discriminate two ............. 0.4s ... [11], [18.25%]
120			4. Plot another ............... 2m 1.5s ..... 21, 0.2% ; hits: 456712/0, 34.2%
121			#endif
122
123			// aux struct collecting strings per handler
124			struct StrItem {
125			std::string label, elapsed, nDiscriminated, percentage, hitsStats;
126			};
127
128			void
129		✗	iEvStatProcInfo::print_summary(std::ostream & os) {
130			// TODO: sub-pipe is not supported so far...
131		✗	const size_t nItems = _ordered.size();
132		✗	size_t fieldWidth[] = {0, 0, 0, 0, 0}; // label, elpased, disc, perc, hitsStats
133		✗	std::vector<StrItem> strItems;
134		✗	strItems.reserve(nItems);
135
136		✗	os << "Handlers summary:" << std::endl;
137			char strBf[64];
138		✗	size_t nEventsSurvived = _nEvsProcessed
139		✗	, nDiscriminatedOverall = 0;
140		✗	size_t nItem = 0;
141		✗	for(auto handlerStatsEntry : _ordered) {
142		✗	++nItem;
143		✗	StrItem strItem;
144
145			// handler number + label
146		✗	size_t labelLength = snprintf(strBf, sizeof(strBf)
147		✗	, "%3lu. %s", nItem + 1, handlerStatsEntry->name.c_str() );
148		✗	if(fieldWidth[0] < labelLength) fieldWidth[0] = labelLength;
149		✗	strItem.label = strBf;
150			// elapsed time
151		✗	size_t strTimeLength = abs_sec_to_hr(handlerStatsEntry->elapsed, strBf, sizeof(strBf));
152		✗	if(fieldWidth[1] < strTimeLength) fieldWidth[1] = strTimeLength;
153		✗	strItem.elapsed = strBf;
154			// number of discriminated events
155		✗	size_t nDiscStrLength = snprintf(strBf, sizeof(strBf)
156		✗	, "%lu", handlerStatsEntry->nDiscriminated);
157		✗	if(fieldWidth[2] < nDiscStrLength) fieldWidth[2] = nDiscStrLength;
158		✗	strItem.nDiscriminated = strBf;
159			// discriminated percentage
160			float perc = nEventsSurvived
161		✗	? 100*(static_cast<float>(handlerStatsEntry->nDiscriminated) / nEventsSurvived)
162		✗	: std::numeric_limits<float>::quiet_NaN()
163			;
164			// decrease number of survived events for further usage
165		✗	if(nEventsSurvived)
166		✗	nEventsSurvived -= handlerStatsEntry->nDiscriminated;
167		✗	nDiscriminatedOverall += handlerStatsEntry->nDiscriminated;
168		✗	size_t nPercStrLength = snprintf(strBf, sizeof(strBf), "%4.1f%%", perc);
169		✗	if(fieldWidth[3] < nPercStrLength) fieldWidth[3] = nPercStrLength;
170		✗	strItem.percentage = strBf;
171			// hits stats
172		✗	if(!handlerStatsEntry->hitHandlerPtr) {
173		✗	strItems.push_back(strItem);
174		✗	continue;
175			}
176			// hits stats
177		✗	size_t hitsStatsLen = snprintf(strBf, sizeof(strBf), "%zu/%zu"
178		✗	, handlerStatsEntry->hitHandlerPtr->n_hits_discriminated()
179		✗	, handlerStatsEntry->hitHandlerPtr->n_hits_considered()
180		✗	);
181
182		✗	if(0 != handlerStatsEntry->hitHandlerPtr->n_hits_discriminated()) {
183			float hitsPerc = 100
184		✗	* static_cast<float>(handlerStatsEntry->hitHandlerPtr->n_hits_discriminated())
185		✗	/ handlerStatsEntry->hitHandlerPtr->n_hits_considered()
186			;
187		✗	hitsStatsLen += snprintf(strBf + hitsStatsLen, sizeof(strBf) - hitsStatsLen, ", %.1f%%", hitsPerc);
188			}
189		✗	strItem.hitsStats = strBf;
190		✗	if(fieldWidth[4] < hitsStatsLen) fieldWidth[4] = hitsStatsLen;
191
192		✗	strItems.push_back(strItem);
193			}
194
195		✗	os << std::setw(fieldWidth[0] + 4) << std::left << " #. LABEL"
196		✗	<< std::setw(fieldWidth[1] + 1) << std::right << "ELAPSED"
197		✗	<< std::setw(17) << std::right << "DISCRIMINATED"
198		✗	<< std::endl;
199		✗	for(const auto & strItem : strItems) {
200		✗	os << std::setw(fieldWidth[0]+4) << std::setfill('.') << std::left << strItem.label + " "
201		✗	<< std::setw(fieldWidth[1]+2) << std::setfill('.') << std::right << " " + strItem.elapsed + " "
202		✗	<< std::setw(fieldWidth[2]+4) << std::setfill('.') << std::right << " " + strItem.nDiscriminated
203		✗	<< /*std::setw(fieldWidth[3]) <<*/ std::setfill(' ') << std::left << ", " + strItem.percentage;
204		✗	if(!strItem.hitsStats.empty())
205		✗	os /* << std::setw(fieldWidth[4])*/ << " ; " + strItem.hitsStats;
206		✗	os << std::endl;
207			}
208		✗	abs_sec_to_hr(elapsed(), strBf, sizeof(strBf));
209		✗	std::string elapsedTimeStr(strBf);
210		✗	float evsPerSec = 0.;
211		✗	if(_nEvsProcessed) {
212		✗	evsPerSec = static_cast<float>(_nEvsProcessed)*CLOCKS_PER_SEC / elapsed();
213			}
214		✗	if(evsPerSec < 5e-2) {
215		✗	snprintf(strBf, sizeof(strBf), "%.2e", evsPerSec);
216			} else {
217		✗	snprintf(strBf, sizeof(strBf), "%.2f", evsPerSec);
218			}
219		✗	os << "Overall event processing summary:" << std::endl
220		✗	<< " Time elapsed overall ... " << elapsedTimeStr << " (" << strBf << " ev/s)" << std::endl
221		✗	<< " Events considered ...... " << _nEvsProcessed << std::endl
222		✗	<< " Events discriminated ... " << nDiscriminatedOverall << std::endl;
223			}
224
225			//
226			// Periodic dispatcher
227
228			void
229		✗	EvProcInfoDispatcher::_dispatch_f() {
230		✗	while( _keep ) {
231		✗	std::this_thread::sleep_for(std::chrono::milliseconds(_rrMSec));
232		✗	_m.lock();
233		✗	_update_event_processing_info();
234		✗	_m.unlock();
235			}
236			}
237
238		✗	EvProcInfoDispatcher::EvProcInfoDispatcher( size_t nMaxEvs
239			, unsigned int refreshTime
240		✗	) : iEvStatProcInfo( nMaxEvs )
241		✗	, _rrMSec(refreshTime)
242		✗	, _dispatcherThread(nullptr)
243		✗	, _keep(false)
244		✗	, _processingStartTime(clock()) {
245			}
246		✗	EvProcInfoDispatcher::~EvProcInfoDispatcher() {
247		✗	if( _dispatcherThread ) {
248		✗	_m.lock();
249		✗	_keep = false;
250		✗	_m.unlock();
251		✗	_dispatcherThread->join();
252		✗	delete _dispatcherThread;
253		✗	_dispatcherThread = nullptr;
254			}
255			}
256
257			void
258		✗	EvProcInfoDispatcher::notify_event_read() {
259		✗	std::lock_guard<std::mutex> lock(_m);
260		✗	iEvStatProcInfo::notify_event_read();
261			}
262
263			void
264		✗	EvProcInfoDispatcher::notify_event_discriminated( const AbstractHandler * hPtr ) {
265		✗	std::lock_guard<std::mutex> lock(_m);
266		✗	iEvStatProcInfo::notify_event_discriminated(hPtr);
267			}
268
269			void
270		✗	EvProcInfoDispatcher::notify_handler_starts( const AbstractHandler * hPtr ) {
271		✗	std::lock_guard<std::mutex> lock(_m);
272		✗	iEvStatProcInfo::notify_handler_starts(hPtr);
273			}
274
275			void
276		✗	EvProcInfoDispatcher::notify_handler_done( const AbstractHandler * hPtr ) {
277		✗	std::lock_guard<std::mutex> lock(_m);
278		✗	iEvStatProcInfo::notify_handler_done(hPtr);
279			}
280
281			void
282		✗	EvProcInfoDispatcher::start_event_processing() {
283		✗	assert(!_dispatcherThread);
284		✗	assert(!_keep);
285		✗	_keep = true;
286		✗	_dispatcherThread = new std::thread( &EvProcInfoDispatcher::_dispatch_f
287		✗	, this );
288			}
289
290			void
291		✗	EvProcInfoDispatcher::finalize() {
292			{
293		✗	_m.lock();
294		✗	_keep = false;
295		✗	_m.unlock();
296			}
297		✗	if(_dispatcherThread) {
298		✗	_dispatcherThread->join();
299		✗	delete _dispatcherThread;
300		✗	_dispatcherThread = nullptr;
301			}
302			}
303
304			//
305			// TTY print-out
306
307			void
308		✗	TTYStatusProcessingInfo::_update_event_processing_info() {
309		✗	auto layoutPtr = na64dp::util::StdoutStreamAppender::self();
310		✗	if(layoutPtr) {
311		✗	float elapsed = ((float) clock() - started())/CLOCKS_PER_SEC
312		✗	, rate = ((float) n_events_processed())/(elapsed ? elapsed : 1)
313			;
314
315		✗	std::ostringstream oss;
316		✗	oss << " ";
317		✗	if( n_events_to_process() ) {
318		✗	oss << n_events_processed() << " / "
319		✗	<< n_events_to_process()
320			;
321		✗	if(rate && std::isfinite(rate)) {
322			char buf[64];
323			float reamainedSec
324		✗	= (n_events_to_process() - n_events_processed())/rate;
325		✗	util::seconds_to_hmsm(reamainedSec, buf, sizeof(buf));
326		✗	oss << ", ~" << buf;
327			}
328			} else {
329		✗	oss << n_events_processed();
330			}
331		✗	oss << ", ";
332
333		✗	layoutPtr->update_status_text(oss.str().c_str());
334			}
335			}
336
337			#if 0
338			void
339			PrintEventProcessingInfo::_update_event_processing_info() {
340			float elapsed = ((float) clock() - started())/CLOCKS_PER_SEC
341			, rate = ((float) n_events_processed())/(elapsed ? elapsed : 1)
342			;
343
344			static char bf[1024];
345			// Note: following escape sequences are used (ANSI terminal):
346			// \033[s -- save current cursor position
347			// \033[u -- restore cursor position previously saved
348			// \033[K -- clear line, from current position to end
349			size_t nPrinted = snprintf( bf, sizeof(bf)
350			, "\033[K\033[1m%zu\033[0m events processed in"
351			" \033[1m%.2f\033[0m sec (\033[1m%.1f\033[0m event/sec)\n"
352			, n_events_processed(), elapsed, rate );
353			size_t nHandler = 1;
354			for( auto handlerPair : *this ) {
355			const AbstractHandler * handlerPtr = handlerPair.first;
356			const aux::HandlerStatisticsEntry & hse = handlerPair.second;
357			float perc = 100.*hse.nDiscriminated/((float) n_events_processed());
358			nPrinted += snprintf( bf + nPrinted, sizeof(bf) - nPrinted
359			, "\033[K %2zu : %p %5zu (%4.1f%%) : %s\n"
360			, nHandler, handlerPtr, hse.nDiscriminated
361			, perc, hse.name.c_str() );
362			if( nPrinted >= sizeof(bf) ) {
363			break;
364			}
365			++nHandler;
366			}
367			fprintf(stdout, "\033[%zuA", nHandler);
368			fputs(bf, stdout);
369			fflush(stdout);
370			}
371			#endif
372
373			#if 0 // XXX, kept as a draft for future
374			void
375			EvProcInfoDispatcher::excerpt( std::vector<char> & buffer ) {
376			//std::lock_guard<std::mutex> lock(_m);
377			// TODO: this objects could be probably made reentrant
378			::capnp::MallocMessageBuilder msg;
379			EventProcessingState::Builder state = msg.initRoot<EventProcessingState>();
380			::capnp::List<HandlerStats>::Builder hStates = state.initHandlers( size() );
381
382			// Fill handlers infor
383			int i = 0;
384			std::map<unsigned short, const EventProcessingState *> sorted;
385			for( const aux::HandlerStatisticsEntry * hse : ordered_stats() ) {
386			HandlerStats::Builder hState = hStates[i];
387
388			hState.setEventsDiscriminated( hse->nDiscriminated );
389			hState.setElapsedTime( 1e3*float(hse->elapsed)/CLOCKS_PER_SEC );
390			hState.setName( hse->name );
391			++i;
392			}
393			state.setElapsedTime( 1e3*float(clock() - started())/CLOCKS_PER_SEC );
394			state.setEventsPassed( n_events_processed() );
395			state.setNEventsExpected( n_events_to_process() );
396			// Fill banks info
397			auto banks = state.initBanks(); {
398			banks.setNSADCHits( _banks.bankSADC.capacity() );
399			banks.setNAPVHits( _banks.bankAPV.capacity() );
400			banks.setNSADCFittingEntries( _banks.bankSADCFitting.capacity() );
401			banks.setNAPVClusters( _banks.bankAPVClusters.capacity() );
402			banks.setNTrackPoints( _banks.bankTrackPoints.capacity() );
403			banks.setNTracks( _banks.bankTrackPoints.capacity() );
404			}
405
406			// serialize
407			kj::Array<capnp::word> dataArr = capnp::messageToFlatArray(msg);
408			kj::ArrayPtr<kj::byte> bytes = dataArr.asBytes();
409
410			buffer.resize( bytes.size() );
411			std::copy( bytes.begin(), bytes.end(), buffer.begin() );
412			}
413			#endif
414
415			} // namespace na64
416
417