diff mbox series

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

Message ID k9la7xcvn03.fsf@gmail.com
State Changes Requested
Delegated to: John Crispin
Headers show
Series [LEDE-DEV,v2] procd: add timing to start/stop logging | expand

Commit Message

Karl Vogel Jan. 17, 2018, 9:43 a.m. UTC 
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 <karl.vogel@gmail.com>
---
 rcS.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

Comments

Koen Vandeputte Jan. 17, 2018, 9:54 a.m. UTC | #1 
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 <karl.vogel@gmail.com>
> ---
>   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(&s->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(&tv_stop, NULL);
> +	timersub(&tv_stop, &s->tv_start, &tv_res);
> +	DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, tv_res.tv_sec, tv_res.tv_usec);
>   	ustream_free(&s->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, ...)||||
John Crispin Jan. 17, 2018, 9:56 a.m. UTC | #2 
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 <karl.vogel@gmail.com>
>> ---
>>   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(&s->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(&tv_stop, NULL);
>> +    timersub(&tv_stop, &s->tv_start, &tv_res);
>> +    DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, 
>> tv_res.tv_sec, tv_res.tv_usec);
>>       ustream_free(&s->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
Karl Vogel Jan. 17, 2018, 10:11 a.m. UTC | #3 
John Crispin <john@phrozen.org> 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 <karl.vogel@gmail.com>
>>> ---
>>>  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(&s->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(&tv_stop, NULL);
>>> + timersub(&tv_stop, &s->tv_start, &tv_res);
>>> + DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, 
>>> tv_res.tv_sec, tv_res.tv_usec);
>>>  ustream_free(&s->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
Koen Vandeputte Jan. 17, 2018, 10:33 a.m. UTC | #4 
On 2018-01-17 11:11, Karl Vogel wrote:
> John Crispin <john@phrozen.org> 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 <karl.vogel@gmail.com>
>>>> ---
>>>>   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(&s->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(&tv_stop, NULL);
>>>> + timersub(&tv_stop, &s->tv_start, &tv_res);
>>>> + DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param,
>>>> tv_res.tv_sec, tv_res.tv_usec);
>>>>   ustream_free(&s->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
diff mbox series

Patch

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(&s->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(&tv_stop, NULL);
+	timersub(&tv_stop, &s->tv_start, &tv_res);
+	DEBUG(2, "stop %s %s - took %lu.%06lus\n", s->file, s->param, tv_res.tv_sec, tv_res.tv_usec);
 	ustream_free(&s->fd.stream);
 	close(s->fd.fd.fd);
 	free(s);