1 /* -*- mode: C; c-file-style: "gnu"; indent-tabs-mode: nil; -*- */
2 
3 #include "config.h"
4 
5 #include <string.h>
6 
7 #include "cinnamon-perf-log.h"
8 
9 typedef struct _CinnamonPerfEvent CinnamonPerfEvent;
10 typedef struct _CinnamonPerfStatistic CinnamonPerfStatistic;
11 typedef struct _CinnamonPerfStatisticsClosure CinnamonPerfStatisticsClosure;
12 typedef union  _CinnamonPerfStatisticValue CinnamonPerfStatisticValue;
13 typedef struct _CinnamonPerfBlock CinnamonPerfBlock;
14 
15 /**
16  * SECTION:cinnamon-perf-log
17  * @short_description: Event recorder for performance measurement
18  *
19  * CinnamonPerfLog provides a way for different parts of the code to
20  * record information for subsequent analysis and interactive
21  * exploration. Events exist of a timestamp, an event ID, and
22  * arguments to the event.
23  *
24  * Emphasis is placed on storing recorded events in a compact
25  * fashion so log recording disturbs the execution of the program
26  * as little as possible, however events should not be recorded
27  * at too fine a granularity - an event that is recorded once
28  * per frame or once per user action is appropriate, an event that
29  * occurs many times per frame is not.
30  *
31  * Arguments are identified by a D-Bus style signature; at the moment
32  * only a limited number of event signatures are supported to
33  * simplify the code.
34  */
35 struct _CinnamonPerfLog
36 {
37   GObject parent;
38 
39   GPtrArray *events;
40   GHashTable *events_by_name;
41   GPtrArray *statistics;
42   GHashTable *statistics_by_name;
43 
44   GPtrArray *statistics_closures;
45 
46   GQueue *blocks;
47 
48   gint64 start_time;
49   gint64 last_time;
50 
51   guint statistics_timeout_id;
52 
53   guint enabled : 1;
54 };
55 
56 struct _CinnamonPerfLogClass
57 {
58   GObjectClass parent_class;
59 };
60 
61 struct _CinnamonPerfEvent
62 {
63   guint16 id;
64   char *name;
65   char *description;
66   char *signature;
67 };
68 
69 union _CinnamonPerfStatisticValue
70 {
71   int i;
72   gint64 x;
73 };
74 
75 struct _CinnamonPerfStatistic
76 {
77   CinnamonPerfEvent *event;
78 
79   CinnamonPerfStatisticValue current_value;
80   CinnamonPerfStatisticValue last_value;
81 
82   guint initialized : 1;
83   guint recorded : 1;
84 };
85 
86 struct _CinnamonPerfStatisticsClosure
87 {
88   CinnamonPerfStatisticsCallback callback;
89   gpointer user_data;
90   GDestroyNotify notify;
91 };
92 
93 /* The events in the log are stored in a linked list of fixed size
94  * blocks.
95  *
96  * Note that the power-of-two nature of BLOCK_SIZE here is superficial
97  * since the allocated block has the 'bytes' field and malloc
98  * overhead. The current value is well below the size that will
99  * typically be independently mmapped by the malloc implementation so
100  * it doesn't matter. If we switched to mmapping blocks manually
101  * (perhaps to avoid polluting malloc statistics), we'd want to use a
102  * different value of BLOCK_SIZE.
103  */
104 #define BLOCK_SIZE 8192
105 
106 struct _CinnamonPerfBlock
107 {
108   guint32 bytes;
109   guchar buffer[BLOCK_SIZE];
110 };
111 
112 /* Number of milliseconds between periodic statistics collection when
113  * events are enabled. Statistics collection can also be explicitly
114  * triggered.
115  */
116 #define STATISTIC_COLLECTION_INTERVAL_MS 5000
117 
118 /* Builtin events */
119 enum {
120   EVENT_SET_TIME,
121   EVENT_STATISTICS_COLLECTED
122 };
123 
124 G_DEFINE_TYPE(CinnamonPerfLog, cinnamon_perf_log, G_TYPE_OBJECT);
125 
126 static gint64
get_time(void)127 get_time (void)
128 {
129   GTimeVal timeval;
130 
131   g_get_current_time (&timeval);
132 
133   return timeval.tv_sec * G_GINT64_CONSTANT(1000000) + timeval.tv_usec;
134 }
135 
136 static void
cinnamon_perf_log_init(CinnamonPerfLog * perf_log)137 cinnamon_perf_log_init (CinnamonPerfLog *perf_log)
138 {
139   perf_log->events = g_ptr_array_new ();
140   perf_log->events_by_name = g_hash_table_new (g_str_hash, g_str_equal);
141   perf_log->statistics = g_ptr_array_new ();
142   perf_log->statistics_by_name = g_hash_table_new (g_str_hash, g_str_equal);
143   perf_log->statistics_closures = g_ptr_array_new ();
144   perf_log->blocks = g_queue_new ();
145 
146   /* This event is used when timestamp deltas are greater than
147    * fits in a gint32. 0xffffffff microseconds is about 70 minutes, so this
148    * is not going to happen in normal usage. It might happen if performance
149    * logging is enabled some time after starting Cinnamon */
150   cinnamon_perf_log_define_event (perf_log, "perf.setTime", "", "x");
151   g_assert (perf_log->events->len == EVENT_SET_TIME + 1);
152 
153   /* The purpose of this event is to allow us to optimize out storing
154    * statistics that haven't changed. We want to mark every time we
155    * collect statistics even if we don't record any individual
156    * statistics so that we can distinguish sudden changes from gradual changes.
157    *
158    * The argument is the number of microseconds that statistics collection
159    * took; we record that since statistics collection could start taking
160    * significant time if we do things like grub around in /proc/
161    */
162   cinnamon_perf_log_define_event (perf_log, "perf.statisticsCollected",
163                                "Finished collecting statistics",
164                                "x");
165   g_assert (perf_log->events->len == EVENT_STATISTICS_COLLECTED + 1);
166 
167   perf_log->start_time = perf_log->last_time = get_time();
168 }
169 
170 static void
cinnamon_perf_log_class_init(CinnamonPerfLogClass * class)171 cinnamon_perf_log_class_init (CinnamonPerfLogClass *class)
172 {
173 }
174 
175 /**
176  * cinnamon_perf_log_get_default:
177  *
178  * Gets the global singleton performance log. This is initially disabled
179  * and must be explicitly enabled with cinnamon_perf_log_set_enabled().
180  *
181  * Return value: (transfer none): the global singleton performance log
182  */
183 CinnamonPerfLog *
cinnamon_perf_log_get_default(void)184 cinnamon_perf_log_get_default (void)
185 {
186   static CinnamonPerfLog *perf_log;
187 
188   if (perf_log == NULL)
189     perf_log = g_object_new (CINNAMON_TYPE_PERF_LOG, NULL);
190 
191   return perf_log;
192 }
193 
194 static gboolean
statistics_timeout(gpointer data)195 statistics_timeout (gpointer data)
196 {
197   CinnamonPerfLog *perf_log = data;
198 
199   cinnamon_perf_log_collect_statistics (perf_log);
200 
201   return TRUE;
202 }
203 
204 /**
205  * cinnamon_perf_log_set_enabled:
206  * @perf_log: a #CinnamonPerfLog
207  * @enabled: whether to record events
208  *
209  * Sets whether events are currently being recorded.
210  */
211 void
cinnamon_perf_log_set_enabled(CinnamonPerfLog * perf_log,gboolean enabled)212 cinnamon_perf_log_set_enabled (CinnamonPerfLog *perf_log,
213                             gboolean      enabled)
214 {
215   enabled = enabled != FALSE;
216 
217   if (enabled != perf_log->enabled)
218     {
219       perf_log->enabled = enabled;
220 
221       if (enabled)
222         {
223           perf_log->statistics_timeout_id = g_timeout_add (STATISTIC_COLLECTION_INTERVAL_MS,
224                                                            statistics_timeout,
225                                                            perf_log);
226         }
227       else
228         {
229           if (perf_log->statistics_timeout_id){
230             g_source_remove (perf_log->statistics_timeout_id);
231             perf_log->statistics_timeout_id = 0;
232           }
233         }
234     }
235 }
236 
237 static CinnamonPerfEvent *
define_event(CinnamonPerfLog * perf_log,const char * name,const char * description,const char * signature)238 define_event (CinnamonPerfLog *perf_log,
239               const char   *name,
240               const char   *description,
241               const char   *signature)
242 {
243   CinnamonPerfEvent *event;
244 
245   if (strcmp (signature, "") != 0 &&
246       strcmp (signature, "s") != 0 &&
247       strcmp (signature, "i") != 0 &&
248       strcmp (signature, "x") != 0)
249     {
250       g_warning ("Only supported event signatures are '', 's', 'i', and 'x'\n");
251       return NULL;
252     }
253 
254   if (perf_log->events->len == 65536)
255     {
256       g_warning ("Maximum number of events defined\n");
257       return NULL;
258     }
259 
260   /* We could do stricter validation, but this will break our JSON dumps */
261   if (strchr (name, '"') != NULL)
262     {
263       g_warning ("Event names can't include '\"'");
264       return NULL;
265     }
266 
267   if (g_hash_table_lookup (perf_log->events_by_name, name) != NULL)
268     {
269       g_warning ("Duplicate event for '%s'\n", name);
270       return NULL;
271     }
272 
273   event = g_slice_new (CinnamonPerfEvent);
274 
275   event->id = perf_log->events->len;
276   event->name = g_strdup (name);
277   event->signature = g_strdup (signature);
278   event->description = g_strdup (description);
279 
280   g_ptr_array_add (perf_log->events, event);
281   g_hash_table_insert (perf_log->events_by_name, event->name, event);
282 
283   return event;
284 }
285 
286 /**
287  * cinnamon_perf_log_define_event:
288  * @perf_log: a #CinnamonPerfLog
289  * @name: name of the event. This should of the form
290  *   '<namespace>.<specific event>', for example
291  *   'clutter.stagePaintDone'.
292  * @description: human readable description of the event.
293  * @signature: signature defining the arguments that event takes.
294  *   This is a string of type characters, using the same characters
295  *   as D-Bus or GVariant. Only a very limited number of signatures
296  *   are supported: , '', 's', 'i', and 'x'. This mean respectively:
297  *   no arguments, one string, one 32-bit integer, and one 64-bit
298  *   integer.
299  *
300  * Defines a performance event for later recording.
301  */
302 void
cinnamon_perf_log_define_event(CinnamonPerfLog * perf_log,const char * name,const char * description,const char * signature)303 cinnamon_perf_log_define_event (CinnamonPerfLog *perf_log,
304                              const char   *name,
305                              const char   *description,
306                              const char   *signature)
307 {
308   define_event (perf_log, name, description, signature);
309 }
310 
311 static CinnamonPerfEvent *
lookup_event(CinnamonPerfLog * perf_log,const char * name,const char * signature)312 lookup_event (CinnamonPerfLog *perf_log,
313               const char   *name,
314               const char   *signature)
315 {
316   CinnamonPerfEvent *event = g_hash_table_lookup (perf_log->events_by_name, name);
317 
318   if (G_UNLIKELY (event == NULL))
319     {
320       g_warning ("Discarding unknown event '%s'\n", name);
321       return NULL;
322     }
323 
324   if (G_UNLIKELY (strcmp (event->signature, signature) != 0))
325     {
326       g_warning ("Event '%s'; defined with signature '%s', used with '%s'\n",
327                  name, event->signature, signature);
328       return NULL;
329     }
330 
331   return event;
332 }
333 
334 static void
record_event(CinnamonPerfLog * perf_log,gint64 event_time,CinnamonPerfEvent * event,const guchar * bytes,size_t bytes_len)335 record_event (CinnamonPerfLog   *perf_log,
336               gint64          event_time,
337               CinnamonPerfEvent *event,
338               const guchar   *bytes,
339               size_t          bytes_len)
340 {
341   CinnamonPerfBlock *block;
342   size_t total_bytes;
343   guint32 time_delta;
344   guint32 pos;
345 
346   if (!perf_log->enabled)
347     return;
348 
349   total_bytes = sizeof (gint32) + sizeof (gint16) + bytes_len;
350   if (G_UNLIKELY (bytes_len > BLOCK_SIZE || total_bytes > BLOCK_SIZE))
351     {
352       g_warning ("Discarding oversized event '%s'\n", event->name);
353       return;
354     }
355 
356   if (event_time > perf_log->last_time + G_GINT64_CONSTANT(0xffffffff))
357     {
358       perf_log->last_time = event_time;
359       record_event (perf_log, event_time,
360                     lookup_event (perf_log, "perf.setTime", "x"),
361                     (const guchar *)&event_time, sizeof(gint64));
362       time_delta = 0;
363     }
364   else if (event_time < perf_log->last_time)
365     time_delta = 0;
366   else
367     time_delta = (guint32)(event_time - perf_log->last_time);
368 
369   perf_log->last_time = event_time;
370 
371   if (perf_log->blocks->tail == NULL ||
372       total_bytes + ((CinnamonPerfBlock *)perf_log->blocks->tail->data)->bytes > BLOCK_SIZE)
373     {
374       block = g_new (CinnamonPerfBlock, 1);
375       block->bytes = 0;
376       g_queue_push_tail (perf_log->blocks, block);
377     }
378   else
379     {
380       block = (CinnamonPerfBlock *)perf_log->blocks->tail->data;
381     }
382 
383   pos = block->bytes;
384 
385   memcpy (block->buffer + pos, &time_delta, sizeof (guint32));
386   pos += sizeof (guint32);
387   memcpy (block->buffer + pos, &event->id, sizeof (guint16));
388   pos += sizeof (guint16);
389   memcpy (block->buffer + pos, bytes, bytes_len);
390   pos += bytes_len;
391 
392   block->bytes = pos;
393 }
394 
395 /**
396  * cinnamon_perf_log_event:
397  * @perf_log: a #CinnamonPerfLog
398  * @name: name of the event
399  *
400  * Records a performance event with no arguments.
401  */
402 void
cinnamon_perf_log_event(CinnamonPerfLog * perf_log,const char * name)403 cinnamon_perf_log_event (CinnamonPerfLog *perf_log,
404                       const char   *name)
405 {
406   CinnamonPerfEvent *event = lookup_event (perf_log, name, "");
407   if (G_UNLIKELY (event == NULL))
408     return;
409 
410   record_event (perf_log, get_time(), event, NULL, 0);
411 }
412 
413 /**
414  * cinnamon_perf_log_event_i:
415  * @perf_log: a #CinnamonPerfLog
416  * @name: name of the event
417  * @arg: the argument
418  *
419  * Records a performance event with one 32-bit integer argument.
420  */
421 void
cinnamon_perf_log_event_i(CinnamonPerfLog * perf_log,const char * name,gint32 arg)422 cinnamon_perf_log_event_i (CinnamonPerfLog *perf_log,
423                         const char   *name,
424                         gint32        arg)
425 {
426   CinnamonPerfEvent *event = lookup_event (perf_log, name, "i");
427   if (G_UNLIKELY (event == NULL))
428     return;
429 
430   record_event (perf_log, get_time(), event,
431                 (const guchar *)&arg, sizeof (arg));
432 }
433 
434 /**
435  * cinnamon_perf_log_event_x:
436  * @perf_log: a #CinnamonPerfLog
437  * @name: name of the event
438  * @arg: the argument
439  *
440  * Records a performance event with one 64-bit integer argument.
441  */
442 void
cinnamon_perf_log_event_x(CinnamonPerfLog * perf_log,const char * name,gint64 arg)443 cinnamon_perf_log_event_x (CinnamonPerfLog *perf_log,
444                         const char   *name,
445                         gint64        arg)
446 {
447   CinnamonPerfEvent *event = lookup_event (perf_log, name, "x");
448   if (G_UNLIKELY (event == NULL))
449     return;
450 
451   record_event (perf_log, get_time(), event,
452                 (const guchar *)&arg, sizeof (arg));
453 }
454 
455 /**
456  * cinnamon_perf_log_event_s:
457  * @perf_log: a #CinnamonPerfLog
458  * @name: name of the event
459  * @arg: the argument
460  *
461  * Records a performance event with one string argument.
462  */
463 void
cinnamon_perf_log_event_s(CinnamonPerfLog * perf_log,const char * name,const char * arg)464 cinnamon_perf_log_event_s (CinnamonPerfLog *perf_log,
465                          const char   *name,
466                          const char   *arg)
467 {
468   CinnamonPerfEvent *event = lookup_event (perf_log, name, "s");
469   if (G_UNLIKELY (event == NULL))
470     return;
471 
472   record_event (perf_log, get_time(), event,
473                 (const guchar *)arg, strlen (arg) + 1);
474 }
475 
476 /**
477  * cinnamon_perf_log_define_statistic:
478  * @perf_log: a #CinnamonPerfLog
479  * @name: name of the statistic and of the corresponding event.
480  *  This should follow the same guidelines as for cinnamon_perf_log_define_event()
481  * @description: human readable description of the statistic.
482  * @signature: The type of the data stored for statistic. Must
483  *  currently be 'i' or 'x'.
484  *
485  * Defines a statistic. A statistic is a numeric value that is stored
486  * by the performance log and recorded periodically or when
487  * cinnamon_perf_log_collect_statistics() is called explicitly.
488  *
489  * Code that defines a statistic should update it by calling
490  * the update function for the particular data type of the statistic,
491  * such as cinnamon_perf_log_update_statistic_i(). This can be done
492  * at any time, but would normally done inside a function registered
493  * with cinnamon_perf_log_add_statistics_callback(). These functions
494  * are called immediately before statistics are recorded.
495  */
496 void
cinnamon_perf_log_define_statistic(CinnamonPerfLog * perf_log,const char * name,const char * description,const char * signature)497 cinnamon_perf_log_define_statistic (CinnamonPerfLog *perf_log,
498                                  const char   *name,
499                                  const char   *description,
500                                  const char   *signature)
501 {
502   CinnamonPerfEvent *event;
503   CinnamonPerfStatistic *statistic;
504 
505   if (strcmp (signature, "i") != 0 &&
506       strcmp (signature, "x") != 0)
507     {
508       g_warning ("Only supported statistic signatures are 'i' and 'x'\n");
509       return;
510     }
511 
512   event = define_event (perf_log, name, description, signature);
513   if (event == NULL)
514     return;
515 
516   statistic = g_slice_new (CinnamonPerfStatistic);
517   statistic->event = event;
518 
519   statistic->initialized = FALSE;
520   statistic->recorded = FALSE;
521 
522   g_ptr_array_add (perf_log->statistics, statistic);
523   g_hash_table_insert (perf_log->statistics_by_name, event->name, statistic);
524 }
525 
526 static CinnamonPerfStatistic *
lookup_statistic(CinnamonPerfLog * perf_log,const char * name,const char * signature)527 lookup_statistic (CinnamonPerfLog *perf_log,
528                   const char   *name,
529                   const char   *signature)
530 {
531   CinnamonPerfStatistic *statistic = g_hash_table_lookup (perf_log->statistics_by_name, name);
532 
533   if (G_UNLIKELY (statistic == NULL))
534     {
535       g_warning ("Unknown statistic '%s'\n", name);
536       return NULL;
537     }
538 
539   if (G_UNLIKELY (strcmp (statistic->event->signature, signature) != 0))
540     {
541       g_warning ("Statistic '%s'; defined with signature '%s', used with '%s'\n",
542                  name, statistic->event->signature, signature);
543       return NULL;
544     }
545 
546   return statistic;
547 }
548 
549 /**
550  * cinnamon_perf_log_update_statistic_i:
551  * @perf_log: a #CinnamonPerfLog
552  * @name: name of the statistic
553  * @value: new value for the statistic
554  *
555  * Updates the current value of an 32-bit integer statistic.
556  */
557 void
cinnamon_perf_log_update_statistic_i(CinnamonPerfLog * perf_log,const char * name,gint32 value)558 cinnamon_perf_log_update_statistic_i (CinnamonPerfLog *perf_log,
559                                    const char   *name,
560                                    gint32        value)
561 {
562   CinnamonPerfStatistic *statistic;
563 
564   statistic = lookup_statistic (perf_log, name, "i");
565   if (G_UNLIKELY (statistic == NULL))
566       return;
567 
568   statistic->current_value.i = value;
569   statistic->initialized = TRUE;
570 }
571 
572 /**
573  * cinnamon_perf_log_update_statistic_x:
574  * @perf_log: a #CinnamonPerfLog
575  * @name: name of the statistic
576  * @value: new value for the statistic
577  *
578  * Updates the current value of an 64-bit integer statistic.
579  */
580 void
cinnamon_perf_log_update_statistic_x(CinnamonPerfLog * perf_log,const char * name,gint64 value)581 cinnamon_perf_log_update_statistic_x (CinnamonPerfLog *perf_log,
582                                    const char   *name,
583                                    gint64        value)
584 {
585   CinnamonPerfStatistic *statistic;
586 
587   statistic = lookup_statistic (perf_log, name, "x");
588   if (G_UNLIKELY (statistic == NULL))
589       return;
590 
591   statistic->current_value.x = value;
592   statistic->initialized = TRUE;
593 }
594 
595 /**
596  * cinnamon_perf_log_add_statistics_callback:
597  * @perf_log: a #CinnamonPerfLog
598  * @callback: function to call before recording statistics
599  * @user_data: data to pass to @callback
600  * @notify: function to call when @user_data is no longer needed
601  *
602  * Adds a function that will be called before statistics are recorded.
603  * The function would typically compute one or more statistics values
604  * and call a function such as cinnamon_perf_log_update_statistic_i()
605  * to update the value that will be recorded.
606  */
607 void
cinnamon_perf_log_add_statistics_callback(CinnamonPerfLog * perf_log,CinnamonPerfStatisticsCallback callback,gpointer user_data,GDestroyNotify notify)608 cinnamon_perf_log_add_statistics_callback (CinnamonPerfLog               *perf_log,
609                                         CinnamonPerfStatisticsCallback callback,
610                                         gpointer                    user_data,
611                                         GDestroyNotify              notify)
612 {
613   CinnamonPerfStatisticsClosure *closure = g_slice_new (CinnamonPerfStatisticsClosure);
614 
615   closure->callback = callback;
616   closure->user_data = user_data;
617   closure->notify = notify;
618 
619   g_ptr_array_add (perf_log->statistics_closures, closure);
620 }
621 
622 /**
623  * cinnamon_perf_log_collect_statistics:
624  * @perf_log: a #CinnamonPerfLog
625  *
626  * Calls all the update functions added with
627  * cinnamon_perf_log_add_statistics_callback() and then records events
628  * for all statistics, followed by a perf.statisticsCollected event.
629  */
630 void
cinnamon_perf_log_collect_statistics(CinnamonPerfLog * perf_log)631 cinnamon_perf_log_collect_statistics (CinnamonPerfLog *perf_log)
632 {
633   gint64 event_time = get_time ();
634   gint64 collection_time;
635   guint i;
636 
637   if (!perf_log->enabled)
638     return;
639 
640   for (i = 0; i < perf_log->statistics_closures->len; i++)
641     {
642       CinnamonPerfStatisticsClosure *closure;
643 
644       closure = g_ptr_array_index (perf_log->statistics_closures, i);
645       closure->callback (perf_log, closure->user_data);
646     }
647 
648   collection_time = get_time() - event_time;
649 
650   for (i = 0; i < perf_log->statistics->len; i++)
651     {
652       CinnamonPerfStatistic *statistic = g_ptr_array_index (perf_log->statistics, i);
653 
654       if (!statistic->initialized)
655         continue;
656 
657       switch (statistic->event->signature[0])
658         {
659         case 'i':
660           if (!statistic->recorded ||
661               statistic->current_value.i != statistic->last_value.i)
662             {
663               record_event (perf_log, event_time, statistic->event,
664                             (const guchar *)&statistic->current_value.i,
665                             sizeof (gint32));
666               statistic->last_value.i = statistic->current_value.i;
667               statistic->recorded = TRUE;
668             }
669           break;
670         case 'x':
671           if (!statistic->recorded ||
672               statistic->current_value.x != statistic->last_value.x)
673             {
674               record_event (perf_log, event_time, statistic->event,
675                             (const guchar *)&statistic->current_value.x,
676                             sizeof (gint64));
677               statistic->last_value.x = statistic->current_value.x;
678               statistic->recorded = TRUE;
679             }
680           break;
681         default:
682           g_warning("cinnamon_perf_log_collect_statistics: default case");
683           break;
684         }
685     }
686 
687   record_event (perf_log, event_time,
688                 g_ptr_array_index (perf_log->events, EVENT_STATISTICS_COLLECTED),
689                 (const guchar *)&collection_time, sizeof (gint64));
690 }
691 
692 /**
693  * cinnamon_perf_log_replay:
694  * @perf_log: a #CinnamonPerfLog
695  * @replay_function: (scope call): function to call for each event in the log
696  * @user_data: data to pass to @replay_function
697  *
698  * Replays the log by calling the given function for each event
699  * in the log.
700  */
701 void
cinnamon_perf_log_replay(CinnamonPerfLog * perf_log,CinnamonPerfReplayFunction replay_function,gpointer user_data)702 cinnamon_perf_log_replay (CinnamonPerfLog            *perf_log,
703                        CinnamonPerfReplayFunction  replay_function,
704                        gpointer                 user_data)
705 {
706   gint64 event_time = perf_log->start_time;
707   GList *iter;
708 
709   for (iter = perf_log->blocks->head; iter; iter = iter->next)
710     {
711       CinnamonPerfBlock *block = iter->data;
712       guint32 pos = 0;
713 
714       while (pos < block->bytes)
715         {
716           CinnamonPerfEvent *event;
717           guint16 id;
718           guint32 time_delta;
719           GValue arg = { 0, };
720 
721           memcpy (&time_delta, block->buffer + pos, sizeof (guint32));
722           pos += sizeof (guint32);
723           memcpy (&id, block->buffer + pos, sizeof (guint16));
724           pos += sizeof (guint16);
725 
726           if (id == EVENT_SET_TIME)
727             {
728               /* Internal, we don't include in the replay */
729               memcpy (&event_time, block->buffer + pos, sizeof (gint64));
730               pos += sizeof (gint64);
731               continue;
732             }
733           else
734             {
735               event_time += time_delta;
736             }
737 
738           event = g_ptr_array_index (perf_log->events, id);
739 
740           if (strcmp (event->signature, "") == 0)
741             {
742               /* We need to pass something, so pass an empty string */
743               g_value_init (&arg, G_TYPE_STRING);
744             }
745           else if (strcmp (event->signature, "i") == 0)
746             {
747               gint32 l;
748 
749               memcpy (&l, block->buffer + pos, sizeof (gint32));
750               pos += sizeof (gint32);
751 
752               g_value_init (&arg, G_TYPE_INT);
753               g_value_set_int (&arg, l);
754             }
755           else if (strcmp (event->signature, "x") == 0)
756             {
757               gint64 l;
758 
759               memcpy (&l, block->buffer + pos, sizeof (gint64));
760               pos += sizeof (gint64);
761 
762               g_value_init (&arg, G_TYPE_INT64);
763               g_value_set_int64 (&arg, l);
764             }
765           else if (strcmp (event->signature, "s") == 0)
766             {
767               g_value_init (&arg, G_TYPE_STRING);
768               g_value_set_string (&arg, (char *)block->buffer + pos);
769               pos += strlen ((char *)(block->buffer + pos)) + 1;
770             }
771 
772           replay_function (event_time, event->name, event->signature, &arg, user_data);
773           g_value_unset (&arg);
774         }
775     }
776 }
777 
778 static char *
escape_quotes(const char * input)779 escape_quotes (const char *input)
780 {
781   GString *result;
782   const char *p;
783 
784   if (strchr (input, '"') == NULL)
785     return (char *)input;
786 
787   result = g_string_new (NULL);
788   for (p = input; *p; p++)
789     {
790       if (*p == '"')
791         g_string_append (result, "\\\"");
792       else
793         g_string_append_c (result, *p);
794     }
795 
796   return g_string_free (result, FALSE);
797 }
798 
799 static gboolean
write_string(GOutputStream * out,const char * str,GError ** error)800 write_string (GOutputStream *out,
801               const char    *str,
802               GError       **error)
803 {
804   return g_output_stream_write_all (out, str, strlen (str),
805                                     NULL, NULL,
806                                     error);
807 }
808 
809 /**
810  * cinnamon_perf_log_dump_events:
811  * @perf_log: a #CinnamonPerfLog
812  * @out: output stream into which to write the event definitions
813  * @error: location to store #GError, or %NULL
814  *
815  * Dump the definition of currently defined events and statistics, formatted
816  * as JSON, to the specified output stream. The JSON output is an array,
817  * with each element being a dictionary of the form:
818  *
819  * { name: <name of event>,
820  *   description: <descrition of string,
821  *   statistic: true } (only for statistics)
822  *
823  * Return value: %TRUE if the dump succeeded. %FALSE if an IO error occurred
824  */
825 gboolean
cinnamon_perf_log_dump_events(CinnamonPerfLog * perf_log,GOutputStream * out,GError ** error)826 cinnamon_perf_log_dump_events (CinnamonPerfLog   *perf_log,
827                             GOutputStream  *out,
828                             GError        **error)
829 {
830   GString *output;
831   guint i;
832 
833   output = g_string_new (NULL);
834   g_string_append (output, "[ ");
835 
836   for (i = 0; i < perf_log->events->len; i++)
837     {
838       CinnamonPerfEvent *event = g_ptr_array_index (perf_log->events, i);
839       char *escaped_description = escape_quotes (event->description);
840       gboolean is_statistic = g_hash_table_lookup (perf_log->statistics_by_name, event->name) != NULL;
841 
842       if (i != 0)
843         g_string_append (output, ",\n  ");
844 
845       g_string_append_printf (output,
846                                 "{ \"name\": \"%s\",\n"
847                               "    \"description\": \"%s\"",
848                               event->name, escaped_description);
849       if (is_statistic)
850         g_string_append (output, ",\n    \"statistic\": true");
851 
852       g_string_append (output, " }");
853 
854       if (escaped_description != event->description)
855         g_free (escaped_description);
856     }
857 
858   g_string_append (output, " ]");
859 
860   return write_string (out, g_string_free (output, FALSE), error);
861 }
862 
863 typedef struct {
864   GOutputStream *out;
865   GError *error;
866   gboolean first;
867 } ReplayToJsonClosure;
868 
869 static void
replay_to_json(gint64 time,const char * name,const char * signature,GValue * arg,gpointer user_data)870 replay_to_json (gint64      time,
871                 const char *name,
872                 const char *signature,
873                 GValue     *arg,
874                 gpointer    user_data)
875 {
876   ReplayToJsonClosure *closure = user_data;
877   char *event_str;
878 
879   if (closure->error != NULL)
880     return;
881 
882   if (!closure->first)
883     {
884       if (!write_string (closure->out, ",\n  ", &closure->error))
885         return;
886     }
887 
888   closure->first = FALSE;
889 
890   if (strcmp (signature, "") == 0)
891     {
892       event_str = g_strdup_printf ("[%" G_GINT64_FORMAT ", \"%s\"]", time, name);
893     }
894   else if (strcmp (signature, "i") == 0)
895     {
896       event_str = g_strdup_printf ("[%" G_GINT64_FORMAT ", \"%s\", %i]",
897                                    time,
898                                    name,
899                                    g_value_get_int (arg));
900     }
901   else if (strcmp (signature, "x") == 0)
902     {
903       event_str = g_strdup_printf ("[%" G_GINT64_FORMAT ", \"%s\", %"G_GINT64_FORMAT "]",
904                                    time,
905                                    name,
906                                    g_value_get_int64 (arg));
907     }
908   else if (strcmp (signature, "s") == 0)
909     {
910       const char *arg_str = g_value_get_string (arg);
911       char *escaped = escape_quotes (arg_str);
912 
913       event_str = g_strdup_printf ("[%" G_GINT64_FORMAT ", \"%s\", \"%s\"]",
914                                    time,
915                                    name,
916                                    g_value_get_string (arg));
917 
918       if (escaped != arg_str)
919         g_free (escaped);
920     }
921   else
922     {
923       g_assert_not_reached ();
924     }
925 
926   if (!write_string (closure->out, event_str, &closure->error))
927       return;
928 }
929 
930 /**
931  * cinnamon_perf_log_dump_log:
932  * @perf_log: a #CinnamonPerfLog
933  * @out: output stream into which to write the event log
934  * @error: location to store #GError, or %NULL
935  *
936  * Writes the performance event log, formatted as JSON, to the specified
937  * output stream. For performance reasons, the output stream passed
938  * in should generally be a buffered (or memory) output stream, since
939  * it will be written to in small pieces. The JSON output is an array
940  * with the elements of the array also being arrays, of the form
941  * '[' <time>, <event name> [, <event_arg>... ] ']'.
942  *
943  * Return value: %TRUE if the dump succeeded. %FALSE if an IO error occurred
944  */
945 gboolean
cinnamon_perf_log_dump_log(CinnamonPerfLog * perf_log,GOutputStream * out,GError ** error)946 cinnamon_perf_log_dump_log (CinnamonPerfLog   *perf_log,
947                          GOutputStream  *out,
948                          GError        **error)
949 {
950   ReplayToJsonClosure closure;
951 
952   closure.out = out;
953   closure.error = NULL;
954   closure.first = TRUE;
955 
956   if (!write_string (out, "[ ", &closure.error))
957     return FALSE;
958 
959   cinnamon_perf_log_replay (perf_log, replay_to_json, &closure);
960 
961   if (closure.error != NULL)
962     {
963       g_propagate_error (error, closure.error);
964       return FALSE;
965     }
966 
967   if (!write_string (out, " ]", &closure.error))
968     return FALSE;
969 
970   return TRUE;
971 }
972