From 2f1cdcf3790d00fc3e8eedb640f7c8dba4eb1be7 Mon Sep 17 00:00:00 2001 From: Tomasz Sowa Date: Thu, 24 Jun 2021 15:33:44 +0200 Subject: [PATCH] added printing info how much time winix spent in the ezc engine added to Request: timespec timespec_req_stop; timespec timespec_req_diff; timespec timespec_ezc_engine_start; timespec timespec_ezc_engine_stop; --- winixd/core/Makefile.dep | 39 +++++++++++++++++++++++++++++++++----- winixd/core/app.cpp | 25 ++++++++++++++++++++++-- winixd/core/app.h | 1 + winixd/core/loadavg.cpp | 33 +++++++++++++------------------- winixd/core/loadavg.h | 13 +++++++------ winixd/core/misc.cpp | 39 ++++++++++++++++++++++++++++++++++++++ winixd/core/misc.h | 29 ++++++++++++++++++++++++++++ winixd/core/request.cpp | 25 +++++++++++++++++++++++- winixd/core/request.h | 41 +++++++++++++++++++++++++++++++++++++--- 9 files changed, 208 insertions(+), 37 deletions(-) diff --git a/winixd/core/Makefile.dep b/winixd/core/Makefile.dep index 633f21c..b32e08b 100644 --- a/winixd/core/Makefile.dep +++ b/winixd/core/Makefile.dep @@ -826,14 +826,43 @@ loadavg.o: ../../../pikotools/src/membuffer/membuffer.h loadavg.o: ../../../pikotools/src/textstream/types.h filelog.h loadavg.o: ../../../winix/winixd/core/synchro.h loadavg.o: ../../../winix/winixd/core/log.h -loadavg.o: ../../../winix/winixd/core/filelog.h lock.h synchro.h misc.h -loadavg.o: requesttypes.h winix_const.h +loadavg.o: ../../../winix/winixd/core/filelog.h lock.h synchro.h request.h +loadavg.o: requesttypes.h ../../../winix/winixd/models/item.h +loadavg.o: ../../../winix/winixd/models/winixmodel.h +loadavg.o: ../../../morm/src/model.h ../../../morm/src/modelconnector.h +loadavg.o: ../../../morm/src/clearer.h ../../../morm/src/dbconnector.h +loadavg.o: ../../../morm/src/queryresult.h ../../../morm/src/ft.h +loadavg.o: ../../../morm/src/flatconnector.h ../../../morm/src/dbexpression.h +loadavg.o: ../../../morm/src/baseexpression.h ../../../morm/src/morm_types.h +loadavg.o: ../../../morm/src/modelenv.h ../../../morm/src/modeldata.h +loadavg.o: ../../../morm/src/cursorhelper.h ../../../morm/src/finderhelper.h +loadavg.o: ../../../morm/src/fieldvaluehelper.h +loadavg.o: ../../../pikotools/src/convert/text.h +loadavg.o: ../../../morm/src/flatexpression.h +loadavg.o: ../../../morm/src/modelwrapper.h +loadavg.o: ../../../winix/winixd/models/winixmodelconnector.h +loadavg.o: ../../../winix/winixd/models/itemcontent.h +loadavg.o: ../../../winix/winixd/templates/htmltextstream.h +loadavg.o: ../../../winix/winixd/templates/misc.h +loadavg.o: ../../../winix/winixd/templates/localefilter.h +loadavg.o: ../../../winix/winixd/templates/locale.h +loadavg.o: ../../../winix/winixd/core/winixbase.h +loadavg.o: ../../../pikotools/src/convert/patternreplacer.h +loadavg.o: ../../../pikotools/src/convert/strtoint.h +loadavg.o: ../../../pikotools/src/convert/text.h misc.h winix_const.h loadavg.o: ../../../pikotools/src/convert/convert.h loadavg.o: ../../../pikotools/src/convert/inttostr.h loadavg.o: ../../../pikotools/src/convert/patternreplacer.h -loadavg.o: ../../../pikotools/src/convert/strtoint.h -loadavg.o: ../../../pikotools/src/convert/text.h -loadavg.o: ../../../pikotools/src/convert/double.h +loadavg.o: ../../../pikotools/src/convert/double.h ../../../ezc/src/ezc.h +loadavg.o: ../../../ezc/src/generator.h ../../../ezc/src/blocks.h +loadavg.o: ../../../ezc/src/item.h ../../../ezc/src/cache.h +loadavg.o: ../../../ezc/src/functions.h ../../../ezc/src/funinfo.h +loadavg.o: ../../../ezc/src/objects.h ../../../ezc/src/pattern.h +loadavg.o: ../../../ezc/src/outstreams.h ../../../ezc/src/expressionparser.h +loadavg.o: ../../../ezc/src/models.h ../../../ezc/src/patternparser.h +loadavg.o: ../../../winix/winixd/templates/htmltextstream.h +loadavg.o: ../../../winix/winixd/core/textstream.h error.h config.h +loadavg.o: textstream.h ../../../winix/winixd/models/winixmodel.h lock.o: lock.h synchro.h log.o: log.h logmanipulators.h ../../../pikotools/src/log/log.h log.o: ../../../pikotools/src/textstream/textstream.h diff --git a/winixd/core/app.cpp b/winixd/core/app.cpp index 053908f..f73b41c 100644 --- a/winixd/core/app.cpp +++ b/winixd/core/app.cpp @@ -653,13 +653,15 @@ void App::ProcessRequest() model_connector.set_winix_request(cur.request); cur.request->RequestStarts(); - system.load_avg.StartRequest(); + system.load_avg.StartRequest(cur.request); log << log2 << config.log_delimiter << logend; ProcessRequestThrow(); SaveSessionsIfNeeded(); - system.load_avg.StopRequest(); + cur.request->RequestEnds(); + system.load_avg.StopRequest(cur.request); + LogRequestTime(); } catch(const std::exception & e) { @@ -832,11 +834,23 @@ void App::MakePage() if( cur.request->page_generated || !cur.request->redirect_to.empty() || !cur.request->x_sendfile.empty() ) return; + + clock_gettime(CLOCK_REALTIME, &cur.request->timespec_ezc_engine_start); + templates.SetEzcParameters( cur.request->gen_trim_white, cur.request->gen_skip_new_line, cur.request->gen_use_special_chars); templates.Generate(); + clock_gettime(CLOCK_REALTIME, &cur.request->timespec_ezc_engine_stop); + + timespec diff; + calculate_timespec_diff(cur.request->timespec_ezc_engine_start, cur.request->timespec_ezc_engine_stop, diff); + + pt::TextStream str; + timespec_to_stream(diff, str); // IMPROVEME in the future Log can be used directly + + log << log3 << "App: ezc engine took: " << str << "s" << logend; } @@ -2124,6 +2138,13 @@ void App::LogUserGroups() } +void App::LogRequestTime() +{ + pt::TextStream str; + timespec_to_stream(cur.request->timespec_req_diff, str); + log << log2 << "App: request took: " << str << "s" << logend; +} + bool App::DropPrivileges(char * user, char * group) diff --git a/winixd/core/app.h b/winixd/core/app.h index 5a17487..6ff4bcb 100644 --- a/winixd/core/app.h +++ b/winixd/core/app.h @@ -79,6 +79,7 @@ public: void Start(); void Close(); void LogUserGroups(); + void LogRequestTime(); bool Demonize(); void SetStopSignal(); bool WasStopSignal(); diff --git a/winixd/core/loadavg.cpp b/winixd/core/loadavg.cpp index 013f1b1..c184c87 100644 --- a/winixd/core/loadavg.cpp +++ b/winixd/core/loadavg.cpp @@ -56,7 +56,8 @@ LoadAvg::LoadAvg() cache_req_per_sec5 = 0.0; cache_req_per_sec15 = 0.0; - was_stop_request = false; + timespec_old_req_stop.tv_sec = 0; + timespec_old_req_stop.tv_nsec = 0; CreateTable(); } @@ -76,7 +77,8 @@ LoadAvg & LoadAvg::operator=(const LoadAvg & l) cache_req_per_sec5 = l.cache_req_per_sec5; cache_req_per_sec15 = l.cache_req_per_sec15; - was_stop_request = l.was_stop_request; + timespec_old_req_stop.tv_sec = l.timespec_old_req_stop.tv_sec; + timespec_old_req_stop.tv_nsec = l.timespec_old_req_stop.tv_nsec; CreateTable(); @@ -182,14 +184,14 @@ void LoadAvg::CheckTimers() -void LoadAvg::StartRequest() +void LoadAvg::StartRequest(Request * req) { - clock_gettime(CLOCK_REALTIME, &start_req); - - if( was_stop_request ) + if( timespec_old_req_stop.tv_sec != 0 ) { - double dp = (start_req.tv_sec - stop_req.tv_sec); - dp += double(start_req.tv_nsec - stop_req.tv_nsec) / 1000000000.0; // make sure that tv_nsec has signed type + // we got at least one request in the past + timespec diff; + calculate_timespec_diff(timespec_old_req_stop, req->timespec_req_start, diff); + double dp = timespec_to_double(diff); current1.dp += dp; current5.dp += dp; @@ -203,14 +205,9 @@ void LoadAvg::StartRequest() -void LoadAvg::StopRequest() +void LoadAvg::StopRequest(Request * req) { -char buf[50]; - - clock_gettime(CLOCK_REALTIME, &stop_req); - - double dr = (stop_req.tv_sec - start_req.tv_sec); - dr += double(stop_req.tv_nsec - start_req.tv_nsec) / 1000000000.0; // make sure that tv_nsec has signed type + double dr = timespec_to_double(req->timespec_req_diff); current1.dr += dr; current5.dr += dr; @@ -220,11 +217,7 @@ char buf[50]; current5.req += 1; current15.req += 1; - sprintf(buf, "%f", dr); - SetNonZeroDigitsAfterComma(buf, 2); - - log << log2 << "LA: request took: " << buf << "s" << logend; - was_stop_request = true; + timespec_old_req_stop = req->timespec_req_stop; } diff --git a/winixd/core/loadavg.h b/winixd/core/loadavg.h index b585a64..5d41455 100644 --- a/winixd/core/loadavg.h +++ b/winixd/core/loadavg.h @@ -37,6 +37,7 @@ #include #include "winixbase.h" +#include "request.h" namespace Winix @@ -60,8 +61,8 @@ public: LoadAvg & operator=(const LoadAvg & l); LoadAvg(const LoadAvg & l); - void StartRequest(); - void StopRequest(); + void StartRequest(Request * req); + void StopRequest(Request * req); double LoadAvgNow(); // load average withing last WINIX_LOADAVG_GRANULARITY1 seconds double LoadAvg1(); @@ -78,7 +79,7 @@ private: struct Times { double dr; // time for the request (in seconds) - double dp; // time for the pause between requestes (in seconds) + double dp; // time for the pause between requestes(in seconds) long req; // how many requests void Clear() @@ -98,6 +99,8 @@ private: } }; + timespec timespec_old_req_stop; + void CheckTimers(); void UpdateTimer1(); void UpdateTimer5(); @@ -117,9 +120,7 @@ private: void Calculate5(); void Calculate15(); - bool was_stop_request; - timespec start_req, stop_req; - + Times * tab1; size_t len1; diff --git a/winixd/core/misc.cpp b/winixd/core/misc.cpp index 3c790af..ad28e14 100644 --- a/winixd/core/misc.cpp +++ b/winixd/core/misc.cpp @@ -1472,5 +1472,44 @@ bool wide_to_utf8(const std::wstring & wide_string, char * utf8, size_t utf8_siz } +void calculate_timespec_diff(timespec & start, timespec & stop, timespec & result) +{ + /* + * copied from macro timespecsub(tsp, usp, vsp) which is defined in sys/time.h + */ + + result.tv_sec = stop.tv_sec - start.tv_sec; + result.tv_nsec = stop.tv_nsec - start.tv_nsec; + + if( result.tv_nsec < 0 ) + { + result.tv_sec--; + result.tv_nsec += 1000000000L; + } +} + + + +double timespec_to_double(timespec & val) +{ + double val_double = val.tv_sec + val.tv_nsec / 1000000000.0; + return val_double; +} + + +void timespec_to_stream(timespec & val, pt::Stream & stream) +{ + char buf[50]; + + double val_double = timespec_to_double(val); + sprintf(buf, "%g", val_double); + SetNonZeroDigitsAfterComma(buf, 2); + + stream << buf; +} + + + + } // namespace Winix diff --git a/winixd/core/misc.h b/winixd/core/misc.h index d45d4ba..e46dc98 100644 --- a/winixd/core/misc.h +++ b/winixd/core/misc.h @@ -987,6 +987,35 @@ bool wide_to_utf8(const wchar_t * wide_string, char * utf8, size_t utf8_siz bool wide_to_utf8(const std::wstring & wide_string, char * utf8, size_t utf8_size); +/* + * calculate diff between start and stop timespec + * + * if start is greater than stop then the result is negative: + * - result.tv_sec is less than zero + * - result.tv_nsec is greater than or equal to zero (only if start.tv_nsec and stop.tv_nsec are correct values from zero to 1000000000L) + * + * 'double' value can be calculated in this way: + * double res = result.tv_sec + result.tv_nsec / 1000000000.0; + * + */ +void calculate_timespec_diff(timespec & start, timespec & stop, timespec & result); + + +/* + * converts timespec to double in the following way: + * double val_double = val.tv_sec + val.tv_nsec / 1000000000.0; + * + * val.tv_sec can be negative (less than zero) but tv_nsec should be in the range [0, 1000000000.0) + * + */ +double timespec_to_double(timespec & val); + + + +void timespec_to_stream(timespec & val, pt::Stream & stream); + + + } // namespace Winix diff --git a/winixd/core/request.cpp b/winixd/core/request.cpp index 9af6fd3..9e617b1 100644 --- a/winixd/core/request.cpp +++ b/winixd/core/request.cpp @@ -152,6 +152,18 @@ void Request::Clear() start_time = 0; start_date.Clear(); + timespec_req_start.tv_sec = 0; + timespec_req_start.tv_nsec = 0; + timespec_req_stop.tv_sec = 0; + timespec_req_stop.tv_nsec = 0; + timespec_req_diff.tv_sec = 0; + timespec_req_diff.tv_nsec = 0; + + timespec_ezc_engine_start.tv_sec = 0; + timespec_ezc_engine_start.tv_nsec = 0; + timespec_ezc_engine_stop.tv_sec = 0; + timespec_ezc_engine_stop.tv_nsec = 0; + subdomain.clear(); return_info_only = false; info.clear(); @@ -178,13 +190,22 @@ void Request::RequestStarts() { // clearing it is better to use at the end of a request // so starting is much faster + clock_gettime(CLOCK_REALTIME, ×pec_req_start); + timespec_req_stop = timespec_req_start; - start_time = std::time(0); + start_time = timespec_req_start.tv_sec; start_date = start_time; } +void Request::RequestEnds() +{ + clock_gettime(CLOCK_REALTIME, ×pec_req_stop); + calculate_timespec_diff(timespec_req_start, timespec_req_stop, timespec_req_diff); +} + + bool Request::IsPostVar(const wchar_t * var) { @@ -375,6 +396,8 @@ void Request::current_dir(morm::ModelWrapper ** model_wrapper) + + } // namespace Winix diff --git a/winixd/core/request.h b/winixd/core/request.h index aa33f30..0d0d84f 100644 --- a/winixd/core/request.h +++ b/winixd/core/request.h @@ -89,14 +89,48 @@ public: /* - request start time - Time() methods are very slow so it is better to directly use those two values - they are set when a request starts + * request start time + * + * start_time is the same as timespec_req_start.tv_sec + * start_date is a pt::Date converted from start_time + * */ + timespec timespec_req_start; time_t start_time; pt::Date start_date; + /* + * request stop time + * + */ + timespec timespec_req_stop; + + + /* + * request stop time - start time + * + */ + timespec timespec_req_diff; + + + /* + * start time of the ezc engine (html templates) + * + */ + timespec timespec_ezc_engine_start; + + + /* + * end time of the ezc engine (html templates) + * + */ + timespec timespec_ezc_engine_stop; + + + + + /* * @@ -370,6 +404,7 @@ public: void RequestStarts(); + void RequestEnds(); void Clear();