Systemtap: PostgreSQL probe, USE @var(varname) or $varname get all local and global variables
背景
在stap脚本中, 从探针处获取变量的值方法比较多, 可以获取的变量值包括本地变量, 全局变量, 甚至其他代码中的全局变量等.
具体的获取变量的用法可参考 :
http://blog.163.com/digoal@126/blog/static/16387704020138113455697/
使用@var("varname")这种方法, 可以查看的变量值包括PostgreSQL探针所在函数内的本地变量, 全局变量, 甚至Linux内核中的全局变量等.
在PostgreSQL探针中, @var("varname"), $varname使用起来非常方便, 适合没有定义参数的探针, 或者定义了参数但是因为各种原因无法获取正常获取值的(如BUG: http://blog.163.com/digoal@126/blog/static/163877040201391622459221/)
使用举例, 获取全局变量的值 :
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e 'probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("checkpoint__done") {printf("ckpt_bufs_written:%d, ckpt_segs_added:%d, ckpt_segs_removed:%d, ckpt_segs_recycled:%d, NBuffers:%d\n", @var("CheckpointStats")->ckpt_bufs_written, @var("CheckpointStats")->ckpt_segs_added, @var("CheckpointStats")->ckpt_segs_removed, @var("CheckpointStats")->ckpt_segs_recycled, @var("NBuffers"))}'
Pass 1: parsed user script and 96 library script(s) using 151984virt/25256res/2116shr/23892data kb, in 240usr/20sys/251real ms.
ckpt_bufs_written:0, ckpt_segs_added:0, ckpt_segs_removed:0, ckpt_segs_recycled:0, NBuffers:262144
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e 'probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("chepoint__done") {printf("%s\n", @var("CheckpointStats")$$)}'
Pass 1: parsed user script and 96 library script(s) using 152044virt/25248res/2116shr/23952data kb, in 240usr/20sys/252real ms.
{.ckpt_start_t=435378988941962, .ckpt_write_t=435378988942012, .ckpt_sync_t=435378988946510, .ckpt_sync_end_t=435378988946514, .ckpt_end_t=435378988947800, .ckpt_bufs_written=0, .ckpt_segs_added=0, .ckpt_segs_removed=0, .ckpt_segs_recycled=0, .ckpt_sync_rels=0, .ckpt_longest_sync=0, .ckpt_agg_sync_time=0}
使用举例, 获取本地变量的值 :
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e 'probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("chepoint__done") {printf("%s\n", $$locals$$)}'
Pass 1: parsed user script and 96 library script(s) using 152048virt/25248res/2116shr/23956data kb, in 240usr/20sys/251real ms.
shutdown=? checkPoint={.redo=28883378856, .ThisTimeLineID=1, .PrevTimeLineID=1, .fullPageWrites='\001', .nextXidEpoch=0, .nextXid=130667542, .nextOid=57491, .nextMulti=1, .nextMultiOffset=0, .oldestXid=1800, .oldestXidDB=1, .oldestMulti=1, .oldestMultiDB=1, .time=1382063813, .oldestActiveXid=130667542} recptr=28883379016 Insert={.PrevRecord=28883378912, .curridx=0, .currpage=0x7fc1b2ae4000, .currpos="", .RedoRecPtr=28883378856, .forcePageWrites='\000', .fullPageWrites='\001', .exclusiveBackup='\000', .nonExclusiveBackups=0, .lastBackupStart=0} rdata={.data="¨b?1", .len=72, .buffer=0, .buffer_std='\001', .next=0x0} freespace=? _logSegNo=? vxids={.backendId=?, .localTransactionId=?} nvxids=0 __func__="CreateCheckPoint"
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e 'probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("chepoint__done") {printf("%s\n", @var("Insert")$$)}'
Pass 1: parsed user script and 96 library script(s) using 152048virt/25248res/2116shr/23956data kb, in 240usr/10sys/251real ms.
{.PrevRecord=28883379392, .curridx=0, .currpage=0x7fc1b2ae4000, .currpos="", .RedoRecPtr=28883379336, .forcePageWrites='\000', .fullPageWrites='\001', .exclusiveBackup='\000', .nonExclusiveBackups=0, .lastBackupStart=0}
也可以使用$varname的形式获取
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e 'probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("chepoint__done") {printf("%s\n", $Insert$$)}'
Pass 1: parsed user script and 96 library script(s) using 152040virt/25244res/2116shr/23948data kb, in 240usr/10sys/252real ms.
{.PrevRecord=28883381312, .curridx=0, .currpage=0x7fc1b2ae4000, .currpos="", .RedoRecPtr=28883381256, .forcePageWrites='\000', .fullPageWrites='\001', .exclusiveBackup='\000', .nonExclusiveBackups=0, .lastBackupStart=0}
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e 'probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("checkpoint__done") {printf("%s\n", $NBuffers$$)}'
Pass 1: parsed user script and 96 library script(s) using 152044virt/25244res/2116shr/23952data kb, in 240usr/10sys/252real ms.
262144
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e 'probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("chepoint__done") {printf("%s\n", $CheckpointStats$$)}'
Pass 1: parsed user script and 96 library script(s) using 152048virt/25248res/2116shr/23956data kb, in 230usr/10sys/252real ms.
{.ckpt_start_t=435381006985866, .ckpt_write_t=435381006985916, .ckpt_sync_t=435381006990623, .ckpt_sync_end_t=435381006990626, .ckpt_end_t=435381006991807, .ckpt_bufs_written=0, .ckpt_segs_added=0, .ckpt_segs_removed=0, .ckpt_segs_recycled=0, .ckpt_sync_rels=0, .ckpt_longest_sync=0, .ckpt_agg_sync_time=0}
对于没有参数的预定义探针, 要获取所在函数的本地变量或者参数值 :
例如query__plan__start探针 :
src/backend/tcop/postgres.c
/*
* Generate a plan for a single already-rewritten query.
* This is a thin wrapper around planner() and takes the same parameters.
*/
PlannedStmt *
pg_plan_query(Query *querytree, int cursorOptions, ParamListInfo boundParams)
{
PlannedStmt *plan;
/* Utility commands have no plans. */
if (querytree->commandType == CMD_UTILITY)
return NULL;
/* Planner must have a snapshot in case it calls user-defined functions. */
Assert(ActiveSnapshotSet());
TRACE_POSTGRESQL_QUERY_PLAN_START();
[root@db-172-16-3-150 ~]# stap -D MAXSTRINGLEN=100000 --vp 10000 -e '
probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("query__plan__start") {
printf("%s\n", $querytree$$)
}'
Pass 1: parsed user script and 96 library script(s) using 152044virt/25244res/2116shr/23952data kb, in 240usr/10sys/252real ms.
{.type=700, .commandType=1, .querySource=0, .queryId=0, .canSetTag='\001', .utilityStmt=0x0, .resultRelation=0, .hasAggs='\000', .hasWindowFuncs='\000', .hasSubLinks='\000', .hasDistinctOn='\000', .hasRecursive='\000', .hasModifyingCTE='\000', .hasForUpdate='\000', .cteList=0x0, .rtable=0x1e079d8, .jointree=0x1e13578, .targetList=0x1e0aa38, .returningList=0x0, .groupClause=0x0, .havingQual=0x0, .windowClause=0x0, .distinctClause=0x0, .sortClause=0x1e134f8, .limitOffset=0x0, .limitCount=0x0, .rowMarks=0x0, .setOperations=0x0, .constraintDeps=0x0}
参考
1. http://blog.163.com/digoal@126/blog/static/16387704020138113455697/
2. http://blog.163.com/digoal@126/blog/static/163877040201391622459221/
3. http://blog.163.com/digoal@126/blog/static/163877040201391883345365/
4. man stapprobes
CONTEXT VARIABLES
Many of the source-level context variables, such as function parameters, locals, globals visible in the compi-
lation unit, may be visible to probe handlers. They may refer to these variables by prefixing their name with
"$" within the scripts. In addition, a special syntax allows limited traversal of structures, pointers, and
arrays. More syntax allows pretty-printing of individual variables or their groups. See also @cast.
$var refers to an in-scope variable "var". If it’s an integer-like type, it will be cast to a 64-bit int for
systemtap script use. String-like pointers (char *) may be copied to systemtap string values using the
kernel_string or user_string functions.
@var("varname")
an alternative syntax for $varname
@var("varname@src/file.c")
refers to the global (either file local or external) variable varname defined when the file src/file.c
was compiled. The CU in which the variable is resolved is the first CU in the module of the probe point
which matches the given file name at the end and has the shortest file name path (e.g. given
@var("foo@bar/baz.c") and CUs with file name paths src/sub/module/bar/baz.c and src/bar/baz.c the second
CU will be chosen to resolve the (file) global variable foo
$var->field traversal via a structure’s or a pointer’s field. This
generalized indirection operator may be repeated to follow more levels. Note that the . operator is
not used for plain structure members, only -> for both purposes. (This is because "." is reserved for
string concatenation.)
$return
is available in return probes only for functions that are declared with a return value.
$var[N]
indexes into an array. The index given with a literal number or even an arbitrary numeric expression.
A number of operators exist for such basic context variable expressions:
$$vars expands to a character string that is equivalent to
sprintf("parm1=%x ... parmN=%x var1=%x ... varN=%x",
parm1, ..., parmN, var1, ..., varN)
for each variable in scope at the probe point. Some values may be printed as =? if their run-time location
cannot be found.
$$locals
expands to a subset of $$vars for only local variables.
$$parms
expands to a subset of $$vars for only function parameters.
$$return
is available in return probes only. It expands to a string that is equivalent to sprintf("return=%x",
$return) if the probed function has a return value, or else an empty string.
& $EXPR
expands to the address of the given context variable expression, if it is addressable.
@defined($EXPR)
expands to 1 or 0 iff the given context variable expression is resolvable, for use in conditionals such
as
@defined($foo->bar) ? $foo->bar : 0
$EXPR$ expands to a string with all of $EXPR’s members, equivalent to
sprintf("{.a=%i, .b=%u, .c={...}, .d=[...]}",
$EXPR->a, $EXPR->b)
$EXPR$$
expands to a string with all of $var’s members and submembers, equivalent to
sprintf("{.a=%i, .b=%u, .c={.x=%p, .y=%c}, .d=[%i, ...]}",
$EXPR->a, $EXPR->b, $EXPR->c->x, $EXPR->c->y, $EXPR->d[0])
For ".return" probes, context variables other than the "$return" value itself are only available for the func-
tion call parameters. The expressions evaluate to the entry-time values of those variables, since that is when
a snapshot is taken. Other local variables are not generally accessible, since by the time a ".return" probe
hits, the probed function will have already returned.
Arbitrary entry-time expressions can also be saved for ".return" probes using the @entry(expr) operator. For
example, one can compute the elapsed time of a function:
probe kernel.function("do_filp_open").return {
println( get_timeofday_us() - @entry(get_timeofday_us()) )
}