Re: [LEDE-DEV] [PATCH v2] procd: add timing to start/stop logging

[Koen Vandeputte]

On 2018-01-17 11:11, Karl Vogel wrote:

John Crispin  writes:


On 17/01/18 10:54, Koen Vandeputte wrote:


On 2018-01-17 10:43, Karl Vogel wrote:

Shows how long an initd task took, for example:

  procd: stop /etc/init.d/dropbear running - took 0.088824s
  procd: Update service dnsmasq
  procd: Update instance dnsmasq::dnsmasq
  procd: running /etc/init.d/dnsmasq running
  procd: start /etc/init.d/dnsmasq running
  procd: stop /etc/init.d/dnsmasq running - took 0.092586s

Signed-off-by: Karl Vogel 
---
  rcS.c | 7 ++-
  1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/rcS.c b/rcS.c
index dd3b76d..acfb6a0 100644
--- a/rcS.c
+++ b/rcS.c
@@ -37,6 +37,7 @@ static struct runqueue q, r;
  struct initd {
  struct ustream_fd fd;
  struct runqueue_process proc;
+ struct timeval tv_start;
  char *file;
  char *param;
  };
@@ -70,6 +71,7 @@ static void q_initd_run(struct runqueue *q, struct
runqueue_task *t)
  int pipefd[2];
  pid_t pid;
  + gettimeofday(>tv_start, NULL);
  DEBUG(2, "start %s %s \n", s->file, s->param);
  if (pipe(pipefd) == -1) {
  ERROR("Failed to create pipe: %m\n");
@@ -106,8 +108,11 @@ static void q_initd_run(struct runqueue *q,
struct runqueue_task *t)
  static void q_initd_complete(struct runqueue *q, struct
runqueue_task *p)
  {
  struct initd *s = container_of(p, struct initd, proc.task);
+ struct timeval tv_stop, tv_res;
  - DEBUG(2, "stop %s %s \n", s->file, s->param);
+ gettimeofday(_stop, NULL);
+ timersub(_stop, >tv_start, _res);
+ DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param,
tv_res.tv_sec, tv_res.tv_usec);
  ustream_free(>fd.stream);
  close(s->fd.fd.fd);
  free(s);

Isn't it better to use a monotonic time source here to measure elapsed
time?
|This way you avoid racing issues should NTP sync kick in during
execution.


|||clock_gettime(CLOCK_MONOTONIC, ...)

that occurred to me aswell as i was just testing the patch inside a vm :-)

   John

I considered that, but then it would require a bit more logic to do the
subtract, as clock_gettime uses a timespec not a timeval. Nothing
impossible ofcourse, but didn't want to increase the size too much for
debug output that isn't active in 99.9% of the installations.

clock_gettime(CLOCK_MONOTONIC, ... ) is also affected by NTP and
adjtime(), so even that won't be 100% when the clock is adjusted.
True,  but CLOCK_MONOTONIC_RAW is not available afaics, and it's at 
least a lot better than a clocksource

which can jump from year 1970 to year 2018 in a split second :)
(especially for devices using battery powered RTC where it's battery 
depleted)


Koen

Karl



___
Lede-dev mailing list
Lede-dev@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/lede-dev

Re: [LEDE-DEV] [PATCH v2] procd: add timing to start/stop logging

[Karl Vogel]

John Crispin  writes:

> On 17/01/18 10:54, Koen Vandeputte wrote:
>>
>>
>> On 2018-01-17 10:43, Karl Vogel wrote:
>>> Shows how long an initd task took, for example:
>>>
>>>  procd: stop /etc/init.d/dropbear running - took 0.088824s
>>>  procd: Update service dnsmasq
>>>  procd: Update instance dnsmasq::dnsmasq
>>>  procd: running /etc/init.d/dnsmasq running
>>>  procd: start /etc/init.d/dnsmasq running
>>>  procd: stop /etc/init.d/dnsmasq running - took 0.092586s
>>>
>>> Signed-off-by: Karl Vogel 
>>> ---
>>>  rcS.c | 7 ++-
>>>  1 file changed, 6 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/rcS.c b/rcS.c
>>> index dd3b76d..acfb6a0 100644
>>> --- a/rcS.c
>>> +++ b/rcS.c
>>> @@ -37,6 +37,7 @@ static struct runqueue q, r;
>>>  struct initd {
>>>  struct ustream_fd fd;
>>>  struct runqueue_process proc;
>>> + struct timeval tv_start;
>>>  char *file;
>>>  char *param;
>>>  };
>>> @@ -70,6 +71,7 @@ static void q_initd_run(struct runqueue *q, struct 
>>> runqueue_task *t)
>>>  int pipefd[2];
>>>  pid_t pid;
>>>  + gettimeofday(>tv_start, NULL);
>>>  DEBUG(2, "start %s %s \n", s->file, s->param);
>>>  if (pipe(pipefd) == -1) {
>>>  ERROR("Failed to create pipe: %m\n");
>>> @@ -106,8 +108,11 @@ static void q_initd_run(struct runqueue *q, 
>>> struct runqueue_task *t)
>>>  static void q_initd_complete(struct runqueue *q, struct 
>>> runqueue_task *p)
>>>  {
>>>  struct initd *s = container_of(p, struct initd, proc.task);
>>> + struct timeval tv_stop, tv_res;
>>>  - DEBUG(2, "stop %s %s \n", s->file, s->param);
>>> + gettimeofday(_stop, NULL);
>>> + timersub(_stop, >tv_start, _res);
>>> + DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, 
>>> tv_res.tv_sec, tv_res.tv_usec);
>>>  ustream_free(>fd.stream);
>>>  close(s->fd.fd.fd);
>>>  free(s);
>> Isn't it better to use a monotonic time source here to measure elapsed 
>> time?
>> |This way you avoid racing issues should NTP sync kick in during 
>> execution.
>>
>>
>> |||clock_gettime(CLOCK_MONOTONIC, ...)
>
> that occurred to me aswell as i was just testing the patch inside a vm :-)
>
>   John

I considered that, but then it would require a bit more logic to do the
subtract, as clock_gettime uses a timespec not a timeval. Nothing
impossible ofcourse, but didn't want to increase the size too much for
debug output that isn't active in 99.9% of the installations.

clock_gettime(CLOCK_MONOTONIC, ... ) is also affected by NTP and
adjtime(), so even that won't be 100% when the clock is adjusted.

Karl

___
Lede-dev mailing list
Lede-dev@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/lede-dev

Re: [LEDE-DEV] [PATCH v2] procd: add timing to start/stop logging

[John Crispin]

On 17/01/18 10:54, Koen Vandeputte wrote:



On 2018-01-17 10:43, Karl Vogel wrote:

Shows how long an initd task took, for example:

  procd: stop /etc/init.d/dropbear running - took 0.088824s
  procd: Update service dnsmasq
  procd: Update instance dnsmasq::dnsmasq
  procd: running /etc/init.d/dnsmasq running
  procd: start /etc/init.d/dnsmasq running
  procd: stop /etc/init.d/dnsmasq running - took 0.092586s

Signed-off-by: Karl Vogel 
---
  rcS.c | 7 ++-
  1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/rcS.c b/rcS.c
index dd3b76d..acfb6a0 100644
--- a/rcS.c
+++ b/rcS.c
@@ -37,6 +37,7 @@ static struct runqueue q, r;
  struct initd {
  struct ustream_fd fd;
  struct runqueue_process proc;
+    struct timeval tv_start;
  char *file;
  char *param;
  };
@@ -70,6 +71,7 @@ static void q_initd_run(struct runqueue *q, struct 
runqueue_task *t)

  int pipefd[2];
  pid_t pid;
  +    gettimeofday(>tv_start, NULL);
  DEBUG(2, "start %s %s \n", s->file, s->param);
  if (pipe(pipefd) == -1) {
  ERROR("Failed to create pipe: %m\n");
@@ -106,8 +108,11 @@ static void q_initd_run(struct runqueue *q, 
struct runqueue_task *t)
  static void q_initd_complete(struct runqueue *q, struct 
runqueue_task *p)

  {
  struct initd *s = container_of(p, struct initd, proc.task);
+    struct timeval tv_stop, tv_res;
  -    DEBUG(2, "stop %s %s \n", s->file, s->param);
+    gettimeofday(_stop, NULL);
+    timersub(_stop, >tv_start, _res);
+    DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, 
tv_res.tv_sec, tv_res.tv_usec);

  ustream_free(>fd.stream);
  close(s->fd.fd.fd);
  free(s);
Isn't it better to use a monotonic time source here to measure elapsed 
time?
|This way you avoid racing issues should NTP sync kick in during 
execution.



|||clock_gettime(CLOCK_MONOTONIC, ...)


that occurred to me aswell as i was just testing the patch inside a vm :-)

    John


___
Lede-dev mailing list
Lede-dev@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/lede-dev

Re: [LEDE-DEV] [PATCH v2] procd: add timing to start/stop logging

[Koen Vandeputte]

On 2018-01-17 10:43, Karl Vogel wrote:

Shows how long an initd task took, for example:

  procd: stop /etc/init.d/dropbear running - took 0.088824s
  procd: Update service dnsmasq
  procd: Update instance dnsmasq::dnsmasq
  procd: running /etc/init.d/dnsmasq running
  procd: start /etc/init.d/dnsmasq running
  procd: stop /etc/init.d/dnsmasq running - took 0.092586s

Signed-off-by: Karl Vogel 
---
  rcS.c | 7 ++-
  1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/rcS.c b/rcS.c
index dd3b76d..acfb6a0 100644
--- a/rcS.c
+++ b/rcS.c
@@ -37,6 +37,7 @@ static struct runqueue q, r;
  struct initd {
struct ustream_fd fd;
struct runqueue_process proc;
+   struct timeval tv_start;
char *file;
char *param;
  };
@@ -70,6 +71,7 @@ static void q_initd_run(struct runqueue *q, struct 
runqueue_task *t)
int pipefd[2];
pid_t pid;
  
+	gettimeofday(>tv_start, NULL);

DEBUG(2, "start %s %s \n", s->file, s->param);
if (pipe(pipefd) == -1) {
ERROR("Failed to create pipe: %m\n");
@@ -106,8 +108,11 @@ static void q_initd_run(struct runqueue *q, struct 
runqueue_task *t)
  static void q_initd_complete(struct runqueue *q, struct runqueue_task *p)
  {
struct initd *s = container_of(p, struct initd, proc.task);
+   struct timeval tv_stop, tv_res;
  
-	DEBUG(2, "stop %s %s \n", s->file, s->param);

+   gettimeofday(_stop, NULL);
+   timersub(_stop, >tv_start, _res);
+   DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, 
tv_res.tv_sec, tv_res.tv_usec);
ustream_free(>fd.stream);
close(s->fd.fd.fd);
free(s);

Isn't it better to use a monotonic time source here to measure elapsed time?
|This way you avoid racing issues should NTP sync kick in during execution.


|||clock_gettime(CLOCK_MONOTONIC, ...)

___
Lede-dev mailing list
Lede-dev@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/lede-dev

[LEDE-DEV] [PATCH v2] procd: add timing to start/stop logging

[Karl Vogel]

Shows how long an initd task took, for example:

 procd: stop /etc/init.d/dropbear running - took 0.088824s
 procd: Update service dnsmasq
 procd: Update instance dnsmasq::dnsmasq
 procd: running /etc/init.d/dnsmasq running
 procd: start /etc/init.d/dnsmasq running
 procd: stop /etc/init.d/dnsmasq running - took 0.092586s

Signed-off-by: Karl Vogel 
---
 rcS.c | 7 ++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/rcS.c b/rcS.c
index dd3b76d..acfb6a0 100644
--- a/rcS.c
+++ b/rcS.c
@@ -37,6 +37,7 @@ static struct runqueue q, r;
 struct initd {
struct ustream_fd fd;
struct runqueue_process proc;
+   struct timeval tv_start;
char *file;
char *param;
 };
@@ -70,6 +71,7 @@ static void q_initd_run(struct runqueue *q, struct 
runqueue_task *t)
int pipefd[2];
pid_t pid;
 
+   gettimeofday(>tv_start, NULL);
DEBUG(2, "start %s %s \n", s->file, s->param);
if (pipe(pipefd) == -1) {
ERROR("Failed to create pipe: %m\n");
@@ -106,8 +108,11 @@ static void q_initd_run(struct runqueue *q, struct 
runqueue_task *t)
 static void q_initd_complete(struct runqueue *q, struct runqueue_task *p)
 {
struct initd *s = container_of(p, struct initd, proc.task);
+   struct timeval tv_stop, tv_res;
 
-   DEBUG(2, "stop %s %s \n", s->file, s->param);
+   gettimeofday(_stop, NULL);
+   timersub(_stop, >tv_start, _res);
+   DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, 
tv_res.tv_sec, tv_res.tv_usec);
ustream_free(>fd.stream);
close(s->fd.fd.fd);
free(s);
-- 
2.15.1


___
Lede-dev mailing list
Lede-dev@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/lede-dev