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

@@ -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

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)

winixd/core/app.h

@@ -79,6 +79,7 @@ public:
 	void Start();
 	void Close();
 	void LogUserGroups();
+	void LogRequestTime();
 	bool Demonize();
 	void SetStopSignal();
 	bool WasStopSignal();

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;
 }
 
 

winixd/core/loadavg.h

@@ -37,6 +37,7 @@
 
 #include <ctime>
 #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;
 

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
 

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
 

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, &timespec_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, &timespec_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
 
 

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();