cfengine  3.15.4
About: CFEngine is a configuration management system for configuring and maintaining Unix-like computers (using an own high level policy language). Community version.
  Fossies Dox: cfengine-3.15.4.tar.gz  ("unofficial" and yet experimental doxygen-generated source code documentation)  

instrumentation.c
Go to the documentation of this file.
1 /*
2  Copyright 2019 Northern.tech AS
3 
4  This file is part of CFEngine 3 - written and maintained by Northern.tech AS.
5 
6  This program is free software; you can redistribute it and/or modify it
7  under the terms of the GNU General Public License as published by the
8  Free Software Foundation; version 3.
9 
10  This program is distributed in the hope that it will be useful,
11  but WITHOUT ANY WARRANTY; without even the implied warranty of
12  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
13  GNU General Public License for more details.
14 
15  You should have received a copy of the GNU General Public License
16  along with this program; if not, write to the Free Software
17  Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA
18 
19  To the extent this program is licensed as part of the Enterprise
20  versions of CFEngine, the applicable Commercial Open Source License
21  (COSL) may apply to this file if you as a licensee so wish it. See
22  included file COSL.txt.
23 */
24 
25 #include <instrumentation.h>
26 
27 #include <dbm_api.h>
28 #include <files_names.h>
29 #include <item_lib.h>
30 #include <string_lib.h>
31 #include <policy.h>
32 
33 #include <math.h>
34 
35 static void NotePerformance(char *eventname, time_t t, double value);
36 
37 /* Alter this code at your peril. Berkeley DB is very sensitive to errors. */
38 
39 bool TIMING = false;
40 
41 /***************************************************************/
42 
43 struct timespec BeginMeasure()
44 {
45  struct timespec start = { 0 };
46 
47  if (clock_gettime(CLOCK_REALTIME, &start) == -1)
48  {
49  Log(LOG_LEVEL_VERBOSE, "Clock gettime failure. (clock_gettime: %s)", GetErrorStr());
50  }
51  else if (TIMING)
52  {
53  Log(LOG_LEVEL_VERBOSE, "T: Starting measuring time");
54  }
55 
56  return start;
57 }
58 
59 /***************************************************************/
60 
61 void EndMeasurePromise(struct timespec start, const Promise *pp)
62 {
63  char id[CF_BUFSIZE], *mid = NULL;
64 
65  if (TIMING)
66  {
67  Log(LOG_LEVEL_VERBOSE, "\n");
68  Log(LOG_LEVEL_VERBOSE, "T: .........................................................");
69  Log(LOG_LEVEL_VERBOSE, "T: Promise timing summary for %s", pp->promiser);
70  }
71 
72  mid = PromiseGetConstraintAsRval(pp, "measurement_class", RVAL_TYPE_SCALAR);
73 
74  if (mid)
75  {
76  snprintf(id, CF_BUFSIZE, "%s:%s:%.100s", mid, pp->parent_promise_type->name, pp->promiser);
77  Chop(id, CF_EXPANDSIZE);
78  EndMeasure(id, start);
79  }
80  else
81  {
82  if (TIMING)
83  {
84  Log(LOG_LEVEL_VERBOSE, "T: No measurement_class attribute set in action body");
85  }
86  EndMeasure(NULL, start);
87  }
88 
89  if (TIMING)
90  {
91  Log(LOG_LEVEL_VERBOSE, "T: .........................................................");
92  }
93 }
94 
95 /***************************************************************/
96 
97 void EndMeasure(char *eventname, struct timespec start)
98 {
99  struct timespec stop;
100 
101  if (clock_gettime(CLOCK_REALTIME, &stop) == -1)
102  {
103  Log(LOG_LEVEL_VERBOSE, "Clock gettime failure. (clock_gettime: %s)", GetErrorStr());
104  }
105  else
106  {
107  double dt = (stop.tv_sec - start.tv_sec) + (stop.tv_nsec - start.tv_nsec) / (double) CF_BILLION;
108 
109  if (eventname)
110  {
111  NotePerformance(eventname, start.tv_sec, dt);
112  }
113  else if (TIMING)
114  {
115  Log(LOG_LEVEL_VERBOSE, "T: This execution measured %lf seconds (use measurement_class to track)", dt);
116  }
117  }
118 }
119 
120 /***************************************************************/
121 
122 int EndMeasureValueMs(struct timespec start)
123 {
124  struct timespec stop;
125 
126  if (clock_gettime(CLOCK_REALTIME, &stop) == -1)
127  {
128  Log(LOG_LEVEL_VERBOSE, "Clock gettime failure. (clock_gettime: %s)", GetErrorStr());
129  }
130  else
131  {
132  double dt = ((stop.tv_sec - start.tv_sec) * 1e3 + /* 1 s = 1e3 ms */
133  (stop.tv_nsec - start.tv_nsec) / 1e6); /* 1e6 ns = 1 ms */
134  return (int)dt;
135  }
136 
137  return -1;
138 }
139 
140 /***************************************************************/
141 
142 static void NotePerformance(char *eventname, time_t t, double value)
143 {
144  CF_DB *dbp;
145  Event e, newe;
146  double lastseen;
147  int lsea = SECONDS_PER_WEEK;
148  time_t now = time(NULL);
149 
150  if (!OpenDB(&dbp, dbid_performance))
151  {
152  return;
153  }
154 
155  if (ReadDB(dbp, eventname, &e, sizeof(e)))
156  {
157  lastseen = now - e.t;
158  newe.t = t;
159 
160  newe.Q = QAverage(e.Q, value, 0.3);
161 
162  /* Have to kickstart variance computation, assume 1% to start */
163 
164  if (newe.Q.var <= 0.0009)
165  {
166  newe.Q.var = newe.Q.expect / 100.0;
167  }
168  }
169  else
170  {
171  lastseen = 0.0;
172  newe.t = t;
173  newe.Q.q = value;
174  newe.Q.dq = 0;
175  newe.Q.expect = value;
176  newe.Q.var = 0.001;
177  }
178 
179  if (lastseen > (double) lsea)
180  {
181  Log(LOG_LEVEL_DEBUG, "Performance record '%s' expired", eventname);
182  DeleteDB(dbp, eventname);
183  }
184  else
185  {
186  WriteDB(dbp, eventname, &newe, sizeof(newe));
187 
188  if (TIMING)
189  {
190  Log(LOG_LEVEL_VERBOSE, "T: This measurement event, alias '%s', measured at time %s\n", eventname, ctime(&newe.t));
191  Log(LOG_LEVEL_VERBOSE, "T: Last measured %lf seconds ago\n", lastseen);
192  Log(LOG_LEVEL_VERBOSE, "T: This execution measured %lf seconds\n", newe.Q.q);
193  Log(LOG_LEVEL_VERBOSE, "T: Average execution time %lf +/- %lf seconds\n", newe.Q.expect, sqrt(newe.Q.var));
194  }
195  }
196 
197  CloseDB(dbp);
198 }
@ RVAL_TYPE_SCALAR
Definition: cf3.defs.h:606
#define SECONDS_PER_WEEK
Definition: cf3.defs.h:73
int clock_gettime(clockid_t clock_id, struct timespec *tp)
Definition: clock_gettime.c:30
bool DeleteDB(DBHandle *handle, const char *key)
Definition: dbm_api.c:583
bool OpenDB(DBHandle **dbp, dbid id)
Definition: dbm_api.c:441
bool ReadDB(DBHandle *handle, const char *key, void *dest, int destSz)
Definition: dbm_api.c:556
bool WriteDB(DBHandle *handle, const char *key, const void *src, int srcSz)
Definition: dbm_api.c:561
void CloseDB(DBHandle *handle)
Definition: dbm_api.c:472
@ dbid_performance
Definition: dbm_api.h:39
#define CF_BUFSIZE
Definition: definitions.h:50
#define CF_EXPANDSIZE
Definition: definitions.h:51
#define CF_BILLION
Definition: definitions.h:32
#define NULL
Definition: getopt1.c:56
static void NotePerformance(char *eventname, time_t t, double value)
void EndMeasure(char *eventname, struct timespec start)
void EndMeasurePromise(struct timespec start, const Promise *pp)
bool TIMING
struct timespec BeginMeasure()
int EndMeasureValueMs(struct timespec start)
const char * GetErrorStr(void)
Definition: logging.c:275
void Log(LogLevel level, const char *fmt,...)
Definition: logging.c:409
@ LOG_LEVEL_DEBUG
Definition: logging.h:47
@ LOG_LEVEL_VERBOSE
Definition: logging.h:46
#define CLOCK_REALTIME
Definition: platform.h:411
void * PromiseGetConstraintAsRval(const Promise *pp, const char *lval, RvalType rtype)
Get the Rval value of the first effective constraint that matches the given type.
Definition: policy.c:3054
QPoint QAverage(QPoint old, double new_q, double p)
Definition: statistics.c:44
int Chop(char *str, size_t max_length)
Remove trailing spaces.
Definition: string_lib.c:1174
QPoint Q
Definition: cf3.defs.h:243
time_t t
Definition: cf3.defs.h:242
char * name
Definition: policy.h:103
PromiseType * parent_promise_type
Definition: policy.h:111
char * promiser
Definition: policy.h:115
double q
Definition: statistics.h:30
double dq
Definition: statistics.h:33
double expect
Definition: statistics.h:31
double var
Definition: statistics.h:32