diff mbox series

[procd] ubus: add state measurement

Message ID 20221026131851.644176-1-fe@dev.tdt.de
State New
Headers show
Series [procd] ubus: add state measurement | expand

Commit Message

Florian Eckert Oct. 26, 2022, 1:18 p.m. UTC
Procd has different states during booting. When the system is
booted, it is in the 'running' state. This state is only exited when the
system is shut down cleanly. This state is called 'shutdown'. To find out
what state the system is in and how long it will take to complete this,
the commit adds a new section 'state' to the ubus call system info. There
you can read which state the procd is in and how long it has been in
this state or how long it has been running in the state.

command:
ubus call system info

output:
{
        "localtime": 1666795909,
        "state": {
                "load": {
                        "active": false,
                        "duration": 42.667914
                },
                "early": {
                        "active": false,
                        "duration": 1.107519
                },
                "ubus": {
                        "active": false,
                        "duration": 0.536634
                },
                "init": {
                        "active": false,
                        "duration": 123.176279
                },
                "running": {
                        "active": true,
                        "duration": 226.491805
                },
                "shutdown": {
                        "active": false,
                        "duration": 0.000000
                }
        },

Signed-off-by: Florian Eckert <fe@dev.tdt.de>
---
This is a followup of pullrequest with the proposed changes.
https://github.com/openwrt/openwrt/pull/10937

 procd.h  |  2 ++
 state.c  | 82 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 system.c |  2 ++
 3 files changed, 86 insertions(+)

Comments

Christian Marangi March 21, 2023, 5:54 p.m. UTC | #1
On Wed, Oct 26, 2022 at 03:18:51PM +0200, Florian Eckert wrote:
> Procd has different states during booting. When the system is
> booted, it is in the 'running' state. This state is only exited when the
> system is shut down cleanly. This state is called 'shutdown'. To find out
> what state the system is in and how long it will take to complete this,
> the commit adds a new section 'state' to the ubus call system info. There
> you can read which state the procd is in and how long it has been in
> this state or how long it has been running in the state.
> 
> command:
> ubus call system info
> 
> output:
> {
>         "localtime": 1666795909,
>         "state": {
>                 "load": {
>                         "active": false,
>                         "duration": 42.667914
>                 },
>                 "early": {
>                         "active": false,
>                         "duration": 1.107519
>                 },
>                 "ubus": {
>                         "active": false,
>                         "duration": 0.536634
>                 },
>                 "init": {
>                         "active": false,
>                         "duration": 123.176279
>                 },
>                 "running": {
>                         "active": true,
>                         "duration": 226.491805
>                 },
>                 "shutdown": {
>                         "active": false,
>                         "duration": 0.000000
>                 }
>         },
> 
> Signed-off-by: Florian Eckert <fe@dev.tdt.de>

Hi, was checking this patch and I'm generally OK for this, just some
question before merging.

I wonder if this kind of thing should be under a config flag?
Like I feel these kind of stats may be needed only for debug purpose?

These are just ideas, if your idea is to use these data for other
purpose than checking process boot time and investigate some regression
then it's totally fine to have this present by default.

Just asking that.
Florian Eckert March 22, 2023, 7:51 a.m. UTC | #2
Hello Christian


> I wonder if this kind of thing should be under a config flag?

I do not see under system, with the command 'ubus -v list system'
a section 'config'. I do not wanted to add a new section, so I
decided to implement it under 'info' because this are runtime
information as 'load', 'memory' ...

> Like I feel these kind of stats may be needed only for debug purpose?

I do not use it only for debug purpose, but also for tracking changes on
boot when  enabling new services in production. I also use this for some
function on my system to check if we have finished booting completly.

> These are just ideas, if your idea is to use these data for other
> purpose than checking process boot time and investigate some regression
> then it's totally fine to have this present by default.

If it doesn't matter from your point of view whether we leave it there 
or
move it somewhere else, then I plead that we leave it as it is. 
Otherwise,
as already mentioned above, we would have to introduce a new function 
section
under 'system', because all other sections unter 'system' have nothing 
to
do with it.

Best regards

Florian
Florian Eckert March 22, 2023, 8:01 a.m. UTC | #3
Hello Oldrich,

>> +
>> +void procd_state_event(struct blob_buf *b)
>> +{
>> +       void *c, *s;
>> +       struct timespec *ts_start;
>> +       struct timespec *ts_stop;
>> +       struct timespec ts_active;
>> +       struct timespec ts_res;
>> +       double duration;
>> +
>> +       c = blobmsg_open_table(b, "state");
>> +
>> +       for (int i = 0; i < __STATE_MAX - 1; i++)
>> +       {
>> +               ts_start = &s_event[i].ts_event;
>> +               ts_stop = &s_event[i+1].ts_event;
> 
> Hi, this looks like out-of-bounds access for the last iteration.
> 

I would say, this is ok, because the loop
'for (int i = 0; i < __STATE_MAX - 1; i++)' does 'i < __STATE_MAX - 1'
and so the STATE_HALT would never hit but could use the memory to read
ts_stop with 'ts_stop = &s_event[i+1].ts_event;'

Best regards

Florian
diff mbox series

Patch

diff --git a/procd.h b/procd.h
index fd29a12..3299b41 100644
--- a/procd.h
+++ b/procd.h
@@ -15,6 +15,7 @@ 
 #ifndef __PROCD_H
 #define __PROCD_H
 
+#include <libubox/blob.h>
 #include <libubox/uloop.h>
 #include <libubox/utils.h>
 #include <libubus.h>
@@ -36,6 +37,7 @@  void ubus_init_system(struct ubus_context *ctx);
 
 void procd_state_next(void);
 void procd_state_ubus_connect(void);
+void procd_state_event(struct blob_buf *b);
 void procd_shutdown(int event);
 void procd_early(void);
 void procd_preinit(void);
diff --git a/state.c b/state.c
index fb81248..acbcece 100644
--- a/state.c
+++ b/state.c
@@ -13,6 +13,7 @@ 
  */
 
 #include <fcntl.h>
+#include <libubox/blob.h>
 #include <pwd.h>
 #include <sys/reboot.h>
 #include <stdio.h>
@@ -20,6 +21,7 @@ 
 #include <unistd.h>
 #include <sys/types.h>
 #include <signal.h>
+#include <time.h>
 
 #include "container.h"
 #include "procd.h"
@@ -43,6 +45,22 @@  enum {
 static int state = STATE_NONE;
 static int reboot_event;
 
+struct state_event {
+	struct timespec ts_event;
+	bool active;
+	const char *name;
+};
+
+static struct state_event s_event[__STATE_MAX] = {
+	[STATE_NONE] = {{0, 0}, true, "load" },
+	[STATE_EARLY] = {{0, 0}, false, "early" },
+	[STATE_UBUS] = {{0, 0}, false, "ubus" },
+	[STATE_INIT] = {{0, 0}, false, "init" },
+	[STATE_RUNNING] = {{0, 0}, false, "running" },
+	[STATE_SHUTDOWN] = {{0, 0}, false, "shutdown" },
+	[STATE_HALT] = {{0, 0}, false, "halt" },
+};
+
 static void set_stdio(const char* tty)
 {
 	if (chdir("/dev") ||
@@ -123,11 +141,23 @@  static void perform_halt()
 		sleep(1);
 }
 
+static void update_state_event(void)
+{
+	// set previous state inactive
+	s_event[state-1].active = false;
+
+	s_event[state].active = true;
+	clock_gettime(CLOCK_BOOTTIME, &s_event[state].ts_event);
+}
+
 static void state_enter(void)
 {
 	char ubus_cmd[] = "/sbin/ubusd";
 	struct passwd *p;
 
+	if (state > STATE_NONE && state < __STATE_MAX)
+		update_state_event();
+
 	switch (state) {
 	case STATE_EARLY:
 		LOG("- early -\n");
@@ -228,3 +258,55 @@  void procd_shutdown(int event)
 	state = STATE_SHUTDOWN;
 	state_enter();
 }
+
+void procd_state_event(struct blob_buf *b)
+{
+	void *c, *s;
+	struct timespec *ts_start;
+	struct timespec *ts_stop;
+	struct timespec ts_active;
+	struct timespec ts_res;
+	double duration;
+
+	c = blobmsg_open_table(b, "state");
+
+	for (int i = 0; i < __STATE_MAX - 1; i++)
+	{
+		ts_start = &s_event[i].ts_event;
+		ts_stop = &s_event[i+1].ts_event;
+
+		if (ts_stop->tv_sec > 0) {
+			ts_res.tv_sec = ts_stop->tv_sec - ts_start->tv_sec;
+			ts_res.tv_nsec = ts_stop->tv_nsec - ts_start->tv_nsec;
+		}
+		else if (s_event[i].active) {
+			clock_gettime(CLOCK_BOOTTIME, &ts_active);
+			ts_res.tv_sec = ts_active.tv_sec - ts_start->tv_sec;
+			ts_res.tv_nsec = ts_active.tv_nsec - ts_start->tv_nsec;
+		}
+		else {
+			ts_res.tv_sec = 0;
+			ts_res.tv_nsec = 0;
+		}
+
+		// correct overflow calculation
+		if (ts_res.tv_nsec < 0) {
+			--ts_res.tv_sec;
+			ts_res.tv_nsec += 1000000000L;
+		}
+		if ( ts_res.tv_sec < 0) {
+			ts_res.tv_sec = ts_start->tv_sec;
+			ts_res.tv_nsec = ts_start->tv_nsec;
+		}
+
+		#define NSEC_PER_SEC 1000000000
+		duration = ((double)(ts_res.tv_sec) + ((double)(ts_res.tv_nsec) / NSEC_PER_SEC));
+
+		s = blobmsg_open_table(b, s_event[i].name);
+		blobmsg_add_u8(b, "active", s_event[i].active);
+		blobmsg_add_double(b, "duration", duration);
+		blobmsg_close_table(b, s);
+	}
+
+	blobmsg_close_table(b, c);
+}
diff --git a/system.c b/system.c
index 93eac59..43c2e94 100644
--- a/system.c
+++ b/system.c
@@ -376,6 +376,8 @@  static int system_info(struct ubus_context *ctx, struct ubus_object *obj,
 
 	blobmsg_add_u32(&b, "localtime", now + tm->tm_gmtoff);
 
+	procd_state_event(&b);
+
 #ifdef linux
 	blobmsg_add_u32(&b, "uptime",    info.uptime);