Tune reader_thread poll timeout value

Tune reader_thread poll timeout value

[Turgis, Frederic]

Hi,

I am following-up remark made in the context of "Making the transport layer more robust" topic. Goal is to reduce number of systemtap wake-ups in the context of embedded low-power use cases like MP3 playback.
The last non tunable or small duration source of wake-up is "reader_thread" ppoll timeout value, every 200ms. We compile systemtap with a value of 2s or more for our daily use.

So I am proposing to introduce tunables below as an example. Don't know if I should have correlated s and ns, also don't know if this should also be applied to relay_old.c. Please tell me if this is an acceptable change:


From 3fac053713be44c00e05423b4f31e2ed8edaa993 Mon Sep 17 00:00:00 2001
From: Frederic Turgis <f-turgis@ti.com>
Date: Wed, 2 May 2012 01:16:28 +0200
Subject: [PATCH] Make reader_thread poll timeout tunable at compilation

---
 runtime/staprun/relay.c |    9 ++++++++-
 1 files changed, 8 insertions(+), 1 deletions(-)

diff --git a/runtime/staprun/relay.c b/runtime/staprun/relay.c
index e08ff60..d81a45f 100644
--- a/runtime/staprun/relay.c
+++ b/runtime/staprun/relay.c
@@ -12,6 +12,13 @@

 #include "staprun.h"

+#ifndef STP_RELAY_TIMEOUT_S
+#define STP_RELAY_TIMEOUT_S 0
+#endif
+#ifndef STP_RELAY_TIMEOUT_NS
+#define STP_RELAY_TIMEOUT_NS 200000000
+#endif
+
 int out_fd[NR_CPUS];
 static pthread_t reader[NR_CPUS];
 static int relay_fd[NR_CPUS];
@@ -125,7 +132,7 @@ static void *reader_thread(void *data)
         char buf[131072];
         int rc, cpu = (int)(long)data;
         struct pollfd pollfd;
-       struct timespec tim = {.tv_sec=0, .tv_nsec=200000000}, *timeout = &tim;
+       struct timespec tim = {.tv_sec=STP_RELAY_TIMEOUT_S, .tv_nsec=STP_RELAY_TIMEOUT_NS}, *timeout = &tim;
        sigset_t sigs;
        off_t wsize = 0;
        int fnum = 0;
--

Regards
FRed

OMAP Platform Business Unit - System Platform Engineering - Platform & Product Entitlement



Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920

Re: Tune reader_thread poll timeout value

[Frank Ch. Eigler]

f-turgis wrote:

> [...]  The last non tunable or small duration source of wake-up is
> "reader_thread" ppoll timeout value, every 200ms. We compile
> systemtap with a value of 2s or more for our daily use.

Do you notice any adverse effects from this?  For an output-heavy
script for example, does this cause more out-of-buffer conditions?


> So I am proposing to introduce tunables below as an example. Don't
> know if I should have correlated s and ns, also don't know if this
> should also be applied to relay_old.c. Please tell me if this is an
> acceptable change:

Looks OK, though I would rather have just one configurable like
   STP_RELAY_TIMEOUT_MS
from which the .tv_sec and .tv_nsec values are calculated.

(Ideally, a baby PLL could regulate this timeout dynamically, adjusted
with the actual ebb and flow of tracing traffic.)

- FChE

Re: Tune reader_thread poll timeout value

[Mark Wielaard]

On Tue, 2012-05-01 at 20:09 +0000, Turgis, Frederic wrote:
> The last non tunable or small duration source of wake-up is
> "reader_thread" ppoll timeout value, every 200ms. We compile systemtap
> with a value of 2s or more for our daily use.
> 
> So I am proposing to introduce tunables below as an example. Don't
> know if I should have correlated s and ns, also don't know if this
> should also be applied to relay_old.c. Please tell me if this is an
> acceptable change:

I agree with Frank that it would be nicer to have one "tunable" instead
of two. Also don't forget to add some small documentation to stap.1
describing the default value and implications of tuning it higher/lower.

Thanks,

Mark

RE: Tune reader_thread poll timeout value

[Turgis, Frederic]

>I agree with Frank that it would be nicer to have one "tunable" instead
>of two
Good that you seem OK with introduction of a tunable. I was not sure about correlating s and ns values, I will follow the suggestion of a MS tunable to derive s and ns values.

> Also don't forget to add some small documentation to stap.1
>describing the default value and implications of tuning it higher/lower.
+ comment from Frank Eigler
>Do you notice any adverse effects from this?  For an output-heavy script for example, does this cause more out-of-buffer conditions?

Several remarks:
- OK for doc. There is a section with MAXNESTING, MAXSTRINGLEN, ... Is it the right place ? It seems it is more related to module itself (like STP_RELAY_TIMER_INTERVAL and STP_CTL_TIMER_INTERVAL that we also use)

- My understanding is that reader_thread ppoll should return (value > 0) on production of a relayfs subbuffer. If timing out, we read an "uncomplete" buffer. So, in case of output-heavy script, we should simply not time-out so tunable should not have any adverse effect.

We keep using 5s tunable and observe (without checking ppoll returned for sub-buffer or timeout):
   * not output-heavy script: waiting 5s before having "probe begin" trace ;-) It seems to print something every k*5 s but script is not producing regularly so I will double check with "probe timer.s(2)" + single trace script to observe behaviour
   * a bit more output-heavy script (scheduler contextswitch, irqs, workqueues, freq changes): I see stapio waking up between 1 to 3s so I imagine ppoll does not return on timeout but on subbuffer production. Everything goes well. I have 1 colleague who checked when systemtap was breaking due to trace bandwidth, I will make him use 2 versions of staprun.

And then submit final patch to review


Regards
Fred

Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920

Re: Tune reader_thread poll timeout value

[Josh Stone]

On 05/02/2012 12:38 PM, Turgis, Frederic wrote:
> - OK for doc. There is a section with MAXNESTING, MAXSTRINGLEN, ...
> Is it the right place ? It seems it is more related to module itself
> (like STP_RELAY_TIMER_INTERVAL and STP_CTL_TIMER_INTERVAL that we
> also use)

That's an important point, that this tunable as you've implemented it is
built into stapio, not into individual modules, so it's much more
static.  Maybe this would be better as a command-line option to
staprun/stapio?  (like the current -b buffer size)

Josh

RE: Tune reader_thread poll timeout value

[Turgis, Frederic]

>That's an important point, that this tunable as you've implemented it is
>built into stapio, not into individual modules, so it's much more
>static.  Maybe this would be better as a command-line option to
>staprun/stapio?  (like the current -b buffer size)

For most people, this tunable is a low-importance item/corner case quite specific to TI so this is why we did not intend to expose it to command line, which is generally more generic and key things to play with.
Thinking about this, we generally prefer high timeout value for Power Management considerations except for "probe timer.s(x)" scripts like iotop.stp where it is interesting to see directly the output. Still, setting tunable to something like 2s would make everyone happy on our side so we would not play with different values on the fly.

But if systemtap experts feel it is worth exposing it like -b option, we will of course patch accordingly, this would be the most flexible solution !

Regards
Fred

Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920

Re: Tune reader_thread poll timeout value

[Mark Wielaard]

On Thu, May 03, 2012 at 12:14:58AM +0000, Turgis, Frederic wrote:
> >That's an important point, that this tunable as you've implemented it is
> >built into stapio, not into individual modules, so it's much more
> >static.  Maybe this would be better as a command-line option to
> >staprun/stapio?  (like the current -b buffer size)
> 
> But if systemtap experts feel it is worth exposing it like -b option,
> we will of course patch accordingly, this would be the most flexible
> solution !

Yes, I think that would be the nicest solution.
I had previously missed this was part of stapio and not of the module
runtime.

Thanks,

Mark

RE: Tune reader_thread poll timeout value

[Turgis, Frederic]

Hi,

>>That's an important point, that this tunable as you've implemented it is
>>built into stapio, not into individual modules, so it's much more
>>static.  Maybe this would be better as a command-line option to
>>staprun/stapio?  (like the current -b buffer size)
>
>But if systemtap experts feel it is worth exposing it like -b option, we will of course patch
>accordingly, this would be the most flexible solution !

1 last point to write and test patch as final as possible:
Did you expect it also as a stap option or staprun option only (I have more or less understood how option is given from stap to staprun_cmd vector to make a staprun command) ?


Regards
Fred

Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920

Re: Tune reader_thread poll timeout value

[Frank Ch. Eigler]

Hi -

f.turgis wrote:

> [...]  1 last point to write and test patch as final as possible:
> Did you expect it also as a stap option or staprun option only [...]

I think it'd be OK to do it as a staprun-only option.  Over time I'd
like to automate the selection of this value rather than expose it
more broadly.

- FChE

RE: Tune reader_thread poll timeout value

[Turgis, Frederic]

>I think it'd be OK to do it as a staprun-only option.  Over time I'd
>like to automate the selection of this value rather than expose it
>more broadly.

Agreed. I test and update the doc then submit the patch to mailing list.

Regards
Fred

Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920

RE: Tune reader_thread poll timeout value

[Turgis, Frederic]

Hi,

Here is proposal for this tunable. I tested on OMAP with value X=50ms, 200ms, 345ms, 1s, 5s, 10s:
- for low throughput trace, stapio wakes up precisely every X ms (scheduler switch probe + awk post-processing). Wakes-up every 200ms if option is not used

- with high value such as 5 seconds, low throughput trace is dumped only every 5s. So of course, do not use probe timer.s(1) to get trace dumped every s on command line, you will have 5 correct infos in 1 shot every 5s.

- no impact in performance, when trace throughput is high, ppoll() returns before timeout expires. For example, an Android video playback fills a buffer in 2 or 3s (scheduler contextswitch + irqs + workqueue monitoring) so 5s timeout expiration is not occuring.


From f70a4385fd709af0079b293f27617e0c2968ae03 Mon Sep 17 00:00:00 2001
From: Frederic Turgis <f-turgis@ti.com>
Date: Tue, 15 May 2012 04:56:14 +0200
Subject: [PATCH] Allow tuning of reader thread ppoll timeout value

Default value of 200ms causes too many wake-ups for embedded platforms
low power use-cases. Timeout of several seconds is expected on these.
New option is -T x where x is timeout in ms.
---
 runtime/staprun/common.c  |   18 ++++++++++++++++--
 runtime/staprun/relay.c   |    5 +++++
 runtime/staprun/staprun.8 |    8 ++++++++
 runtime/staprun/staprun.h |    1 +
 4 files changed, 30 insertions(+), 2 deletions(-)

diff --git a/runtime/staprun/common.c b/runtime/staprun/common.c
index eeb22d5..470f1f9 100644
--- a/runtime/staprun/common.c
+++ b/runtime/staprun/common.c
@@ -23,6 +23,7 @@ int verbose;
 int suppress_warnings;
 int target_pid;
 unsigned int buffer_size;
+unsigned int reader_timeout_ms;
 char *target_cmd;
 char *outfile_name;
 int rename_mod;
@@ -117,6 +118,7 @@ void parse_args(int argc, char **argv)
        suppress_warnings = 0;
        target_pid = 0;
        buffer_size = 0;
+       reader_timeout_ms = 0;
        target_cmd = NULL;
        outfile_name = NULL;
        rename_mod = 0;
@@ -130,7 +132,7 @@ void parse_args(int argc, char **argv)
         remote_id = -1;
         remote_uri = NULL;

-       while ((c = getopt(argc, argv, "ALu::vb:t:dc:o:x:S:DwRr:V")) != EOF) {
+       while ((c = getopt(argc, argv, "ALu::vb:t:dc:o:x:S:DwRr:VT:")) != EOF) {
                switch (c) {
                case 'u':
                        need_uprobes = 1;
@@ -204,6 +206,14 @@ void parse_args(int argc, char **argv)
                               VERSION, GIT_MESSAGE);
                         _exit(1);
                         break;
+               case 'T':
+                       reader_timeout_ms = (unsigned)atoi(optarg);
+                       if (reader_timeout_ms < 1) {
+                               err(_("Invalid reader timeout value '%d' (should be >= 1).\n"), reader_timeout_ms);
+                               usage(argv[0]);
+                       }
+
+                       break;
                default:
                        usage(argv[0]);
                }
@@ -313,7 +323,11 @@ void usage(char *prog)
        "                assumed to be the maximum file size in MB.\n"
        "                When the number of output files reaches N, it\n"
        "                switches to the first output file. You can omit\n"
-       "                the second argument.\n\n"
+       "                the second argument.\n"
+       "-T timeout      Specifies upper limit on amount of time reader thread\n"
+       "                will wait for new trace buffer. Value should be an\n"
+       "                integer >= 1, which is timeout value in ms. Default value is 200ms.\n"
+       "                Purpose is to reduce stapio wake-ups for embedded platforms low-power use cases\n\n"
        "MODULE can be either a module name or a module path.  If a\n"
        "module name is used, it is searched in the following directory:\n"));
         {
diff --git a/runtime/staprun/relay.c b/runtime/staprun/relay.c
index e08ff60..d8ca71b 100644
--- a/runtime/staprun/relay.c
+++ b/runtime/staprun/relay.c
@@ -152,6 +152,11 @@ static void *reader_thread(void *data)
                timeout = NULL;
 #endif
        }
+
+       if (reader_timeout_ms) {
+               timeout->tv_sec = reader_timeout_ms / 1000;
+               timeout->tv_nsec = (reader_timeout_ms - timeout->tv_sec * 1000) * 1000000;
+       }

        pollfd.fd = relay_fd[cpu];
        pollfd.events = POLLIN;
diff --git a/runtime/staprun/staprun.8 b/runtime/staprun/staprun.8
index d87a2e8..bcca07d 100644
--- a/runtime/staprun/staprun.8
+++ b/runtime/staprun/staprun.8
@@ -106,6 +106,14 @@ output files exceed
 .B N
 , systemtap removes the oldest output file. You can omit the second argument.
 .TP
+.B \-T
+Sets maximum time reader thread will wait before dumping trace buffer. Value is
+in ms, default is 200ms. Setting this to a high value decreases number of stapio
+wake-ups, allowing deeper sleep for embedded platforms. But it impacts interactivity
+on terminal as traces are dumped less often in case of low throughput.
+There is no interactivity or performance impact for high throughput as trace is
+dumped when buffer is full, before this timeout expires.
+.TP
 .B var1=val
Sets the value of global variable var1 to val. Global variables contained
 within a module are treated as module options and can be set from the
diff --git a/runtime/staprun/staprun.h b/runtime/staprun/staprun.h
index 3664889..d01a291 100644
--- a/runtime/staprun/staprun.h
+++ b/runtime/staprun/staprun.h
@@ -208,6 +208,7 @@ extern int kernel_ptr_size;
 extern int verbose;
 extern int suppress_warnings;
 extern unsigned int buffer_size;
+extern unsigned int reader_timeout_ms;
 extern char *modname;
 extern char *modpath;
 #define MAXMODOPTIONS 64
--
1.7.1



Regards
Fred


OMAP Platform Business Unit - System Platform Engineering - Platform & Product Entitlement



Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920

-----Original Message-----
From: Turgis, Frederic
Sent: Monday, May 07, 2012 6:09 PM
To: 'Frank Ch. Eigler'
Cc: Josh Stone; Mark Wielaard; systemtap@sourceware.org
Subject: RE: Tune reader_thread poll timeout value

>I think it'd be OK to do it as a staprun-only option.  Over time I'd
>like to automate the selection of this value rather than expose it
>more broadly.

Agreed. I test and update the doc then submit the patch to mailing list.

Regards
Fred

Re: Tune reader_thread poll timeout value

[Frank Ch. Eigler]

Hi, Frederic -


f-turgis wrote:

> [...]
> - with high value such as 5 seconds, low throughput trace is dumped
> only every 5s. So of course, do not use probe timer.s(1) to get
> trace dumped every s on command line, you will have 5 correct infos
> in 1 shot every 5s.
>
> - no impact in performance, when trace throughput is high, ppoll()
> returns before timeout expires. [...]

I'm missing something.  Why does the second item not moot the first?
IOW, if we poll with a 5s timeout, why wouldn't the timer.s(1) reports
wake up the ppoll() to avoid waiting till 5s?


- FChE

RE: Tune reader_thread poll timeout value

[Turgis, Frederic]

> [...]
> - with high value such as 5 seconds, low throughput trace is dumped
> only every 5s. So of course, do not use probe timer.s(1) to get
> trace dumped every s on command line, you will have 5 correct infos
> in 1 shot every 5s.
>
> - no impact in performance, when trace throughput is high, ppoll()
> returns before timeout expires. [...]

I'm missing something.  Why does the second item not moot the first?
IOW, if we poll with a 5s timeout, why wouldn't the timer.s(1) reports
wake up the ppoll() to avoid waiting till 5s?


[FT]
ppoll() wakes-up only when 1 buffer is full. timer.s(1) wakes-up whatever kernel thread (by the way, I should check that with contextswitch trace) but trace throughput is very low. After 5 seconds, ppoll time-outs and the 5 traces done by timer.s(1) at every second are dumped.

When I say "do not use", it is really for interactivity with terminal. People may want to get some small metric every s, but 5 metrics will be displayed every 5s. Of course, for a log read later, you don't care.

So, yes, people should be cautious with this but well, this is for embedded platforms and this is really our goal.

- FChE

Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920

RE: Tune reader_thread poll timeout value

[Turgis, Frederic]

>I'm missing something.  Why does the second item not moot the first?
>IOW, if we poll with a 5s timeout, why wouldn't the timer.s(1) reports
>wake up the ppoll() to avoid waiting till 5s?
>
>
>[FT]
>ppoll() wakes-up only when 1 buffer is full. timer.s(1) wakes-up whatever kernel thread (by the way, I
>should check that with contextswitch trace) but trace throughput is very low. After 5 seconds, ppoll
>time-outs and the 5 traces done by timer.s(1) at every second are dumped.
>
>When I say "do not use", it is really for interactivity with terminal. People may want to get some
>small metric every s, but 5 metrics will be displayed every 5s. Of course, for a log read later, you
>don't care.
>
>So, yes, people should be cautious with this but well, this is for embedded platforms and this is
>really our goal.


Does it make sense then ? In case of low throughput use cases, we have been for a long time dumping buffers only every few s isntead of 200us at the cost of printing latency. Rare cases but needed.

Regards
Fred

Texas Instruments France SA, 821 Avenue Jack Kilby, 06270 Villeneuve Loubet. 036 420 040 R.C.S Antibes. Capital de EUR 753.920