Re: Better pagecache statistics ?

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Re: Better pagecache statistics ?

Marcelo Tosatti

Badari, any improvements on the {add_to,remove_from}_page_cache hooks?

> I just started playing with SystemTap yesterday. First
> thing I want to record is "what is the latency of
> direct reclaim".

I've come up with something which works, though pretty dumb and
inefficient.

I'm facing three problems, maybe someone has a clue on how to improve
the situation.

a) nanosecond timekeeping

Since the systemtap language does not support "struct" abstraction, but
simply "long/string/array" types, there is no way to easily return more
than one value from a function. Is it possible to pass references down
to functions so as to return more than one value?

I failed to find any way to do that.

For nanosecond timekeeping one needs second/nanosecond tuple (struct
timespec).

b) ERROR: MAXACTION exceeded near identifier 'log' at ttfp_delay.stp:49:3

The array size is capped to a maximum. Is there any way to configure
SystemTap to periodically dump-and-zero the arrays? This makes lots of
sense to any statistical gathering code.

c) Hash tables

It would be better to store the log entries in a hash table, the present
script uses the "current" pointer as a key into a pair of arrays,
incrementing the key until a free one is found (which can be very
inefficient).

A hash table would be much more efficient, but allocating memory inside
the scripts is tricky. A pre-allocated, pre-sized pool of memory could
work well for this purpose. The "dump-array-entries-to-userspace" action
could be used to free them.

So both b) and c) could be fixed with the same logic:

- dump entries to userspace if memory pool is getting short
on free entries.
- periodically dump entries to userspace (akin to "bdflush").

And finally, there seems to be a bug which results in _very_ large
(several seconds) delays - that seems unlikely to really happening.

Thoughts?

/*
 * ttfp_delay - measure direct reclaim latency
 */

global count_try_to_free_pages
global count_exit_try_to_free_pages

global entry_array_us
global exit_array_us

global entry_array_ms
global exit_array_ms

function get_currentpointer:long () %{
        THIS->__retvalue = (int) current;
%}

probe kernel.function("try_to_free_pages")
{
        current_p = get_currentpointer();
        ++count_try_to_free_pages;
        while (entry_array_us[current_p])
                ++current_p;

        entry_array_us[current_p] = gettimeofday_us();
        entry_array_ms[current_p] = gettimeofday_ms();
}

probe kernel.function("try_to_free_pages").return
{
        current_p = get_currentpointer();
        ++count_exit_try_to_free_pages;
        while (exit_array_us[current_p])
                ++current_p;

        exit_array_us[current_p] = gettimeofday_us();
        exit_array_ms[current_p] = gettimeofday_ms();
}

probe begin { log("starting probe") }

probe end
{
        log("ending probe")
        log ("calls to try_to_free_pages: " . string(count_try_to_free_pages));
        log ("returns from try_to_free_pages: " . string(count_exit_try_to_free_pages));
        foreach(var in entry_array_us) {
                pos++;
                log ("try_to_free_pages (" . string(pos) .  ") delta: " . string(exit_array_us[var] - entry_array_us[var]) . "us " .string (exit_array_ms[var] - entry_array_ms[var]) . "ms ");
        }

}


example output, running a 800MB "dd" copy on the background.

[root@dmt examples]# stap -g ttfp_delay.stp
starting probe
ending probe
calls to try_to_free_pages: 387
returns from try_to_free_pages: 373
try_to_free_pages (1) delta: 15028us 15ms
try_to_free_pages (2) delta: 47677211us 47677ms
try_to_free_pages (3) delta: 39us 0ms
try_to_free_pages (4) delta: 35us 0ms
try_to_free_pages (5) delta: 152us 0ms
try_to_free_pages (6) delta: 104us 0ms
try_to_free_pages (7) delta: 353us 0ms
try_to_free_pages (8) delta: 61us 0ms
try_to_free_pages (9) delta: 187us 0ms
try_to_free_pages (10) delta: 55us 0ms
try_to_free_pages (11) delta: 50us 0ms
try_to_free_pages (12) delta: 30us 0ms
try_to_free_pages (13) delta: 31us 0ms
try_to_free_pages (14) delta: 42us 0ms
try_to_free_pages (15) delta: 37us 0ms
try_to_free_pages (16) delta: 178us 0ms
try_to_free_pages (17) delta: 34us 0ms
try_to_free_pages (18) delta: 37us 0ms
try_to_free_pages (19) delta: 35us 0ms
try_to_free_pages (20) delta: 34us 0ms
try_to_free_pages (21) delta: 65us 0ms
...

Reply | Threaded
Open this post in threaded view
|

Re: Better pagecache statistics ?

Tom Zanussi
Marcelo Tosatti writes:

[...]

 >
 > b) ERROR: MAXACTION exceeded near identifier 'log' at ttfp_delay.stp:49:3
 >
 > The array size is capped to a maximum. Is there any way to configure
 > SystemTap to periodically dump-and-zero the arrays? This makes lots of
 > sense to any statistical gathering code.
 >
 > c) Hash tables
 >
 > It would be better to store the log entries in a hash table, the present
 > script uses the "current" pointer as a key into a pair of arrays,
 > incrementing the key until a free one is found (which can be very
 > inefficient).
 >
 > A hash table would be much more efficient, but allocating memory inside
 > the scripts is tricky. A pre-allocated, pre-sized pool of memory could
 > work well for this purpose. The "dump-array-entries-to-userspace" action
 > could be used to free them.
 >
 > So both b) and c) could be fixed with the same logic:
 >
 > - dump entries to userspace if memory pool is getting short
 > on free entries.
 > - periodically dump entries to userspace (akin to "bdflush").

Hi,

There's a sytemtap example that does something similar to what you're
describing - see the kmalloc-stacks/kmalloc-top examples in the
testsuite:

systemtap/tests/systemtap.samples/kmalloc-stacks.stp
systemtap/tests/systemtap.samples/kmalloc-top

Basically, the kmalloc-stacks.stp script hashes data in a systemtap
hash and periodically formats the current contents of the hash table
into a convenient form and writes it to userspace, then clears the
hash for the next go-round.  kmalloc-top is a companion Perl script
'daemon' that sits around in userspace waiting for new batches of hash
data, which it then adds to a continuously accumulating Perl hash in
the user-side script.  There's a bit more detail about the script(s)
here:

http://sourceware.org/ml/systemtap/2005-q3/msg00550.html

HTH,

Tom


Reply | Threaded
Open this post in threaded view
|

Re: Better pagecache statistics ?

Frank Ch. Eigler
In reply to this post by Marcelo Tosatti
Hi -

> [...]
> a) nanosecond timekeeping
> Since the systemtap language does not support "struct" abstraction, but
> simply "long/string/array" types, there is no way to easily return more
> than one value from a function. Is it possible to pass references down
> to functions so as to return more than one value?

We don't support references (this enables stricter and simpler
checking), nor multiple return values (though we could - suggest a
good syntax for extracting tuple parts!).

> [...]
> For nanosecond timekeeping one needs second/nanosecond tuple (struct
> timespec).

Are you sure you need something beyond the 64-bit signed integers that
systemtap uses for all its numerics?


> b) ERROR: MAXACTION exceeded near identifier 'log' at ttfp_delay.stp:49:3
> The array size is capped to a maximum.

The MAXACTION limit is associated with code execution, not reserved
sizes for arrays (MAXMAPENTRIES ?).  These values can be overridden
from the stap command line using -D.

> Is there any way to configure SystemTap to periodically
> dump-and-zero the arrays? This makes lots of sense to any
> statistical gathering code.

As mentioned in the other message, a script programmer can do this
with several kinds of explicit code.


> c) Hash tables It would be better to store the log entries in a hash
> table, the present script uses the "current" pointer as a key into a
> pair of arrays, [...]

Systemtap arrays *are* associative, and use hash tables.  Consider
using the pid() or tgid() value to index into them.

> And finally, there seems to be a bug which results in _very_ large
> (several seconds) delays - that seems unlikely to really happening.

That is strange, though I recall hearing of vm problems that might
manifest themselves like that.  Or maybe your "current"-pointer based
indexing is unintentionally colliding.  Consider setting extra probe
points deeper down.


- FChE