|
Tetsuo Handa <penguin-kernel@...>
Hello. I noticed that b0f891d129a9b372 ("Force udst ctx->#reg load to be volatile") broke an USDT probe example shown below. ---------- #!/usr/bin/python from bcc import BPF, USDT import sys import ctypes as ct def usage(): print("USAGE: usdt PID") exit() if len(sys.argv) < 1: usage() if sys.argv[1][0:1] == "-": usage() pid = int(sys.argv[1]) QUERY_MAX = 504 bpf_text = """ #include <uapi/linux/ptrace.h> #define QUERY_MAX """ + str(QUERY_MAX) + """ BPF_PERF_OUTPUT(events); int do_start(struct pt_regs *ctx) { char *cp = NULL; bpf_usdt_readarg(1, ctx, &cp); struct { char query[QUERY_MAX]; } data = { }; bpf_probe_read(&data.query, sizeof(data.query), (void *) cp); events.perf_submit(ctx, &data, sizeof(data)); return 0; }; """ u = USDT(pid=pid) u.enable_probe(probe="query__start", fn_name="do_start") b = BPF(text=bpf_text, usdt_contexts=[u]) class Data(ct.Structure): _fields_ = [ ("query", ct.c_char * QUERY_MAX) ] def print_event(cpu, data, size): event = ct.cast(data, ct.POINTER(Data)).contents print("%s" % (event.query)) b["events"].open_perf_buffer(print_event, page_cnt=64) while 1: b.kprobe_poll() ---------- Since bpf_probe_read() no longer reads PostgreSQL query string passed to query__start event, nothing is printed out. (Oh, I forgot to check whether cp != NULL. Maybe it is bpf_usdt_readarg() which got broken?) # git bisect log # bad: [505c110a5f4f48cff1a501f8b83a548ade6a7739] Add a python test for usdt # good: [aa4543ff2d42a2ca38a52963af9d6d078e48809a] Mention that linux-headers deb must be installed. git bisect start '505c110a5f4f48cff1a501f8b83a548ade6a7739' 'aa4543ff2d42a2ca38a52963af9d6d078e48809a' # good: [a934c903583c415ebed70d03a6c15e9b20c52efa] Add linux/sched.h to list of libbpf.c includes git bisect good a934c903583c415ebed70d03a6c15e9b20c52efa # bad: [cb8e704ca64de58aab6137faa0b8d6b96f24a257] Merge pull request #1212 from iovisor/yhs_dev git bisect bad cb8e704ca64de58aab6137faa0b8d6b96f24a257 # bad: [b0f891d129a9b372e7e8af5b951a1b63985afe26] Force udst ctx->#reg load to be volatile git bisect bad b0f891d129a9b372e7e8af5b951a1b63985afe26 # good: [e7b0ab2dc44b244ef6600630c4e7b16c1f3b123a] Merge pull request #1211 from iovisor/libbpf_c_includes git bisect good e7b0ab2dc44b244ef6600630c4e7b16c1f3b123a # first bad commit: [b0f891d129a9b372e7e8af5b951a1b63985afe26] Force udst ctx->#reg load to be volatile
|
|
Tetsuo,
I cannot reproduce the issue.
The transformation from:
dest = ctx->bx;
to:
dest = *(volatile uint64_t *)&ctx->bx;
should be safe.
I launched a psql console and did a query:
...
yhs=> SELECT order_id FROM order_details;
order_id
----------
6
(1 row)
...
On the usdt side, I did not see anything printout.
I hacked the code to forcefully emit a meaningful string, but it does
not print either. So it looks like the probe function is not called.
int do_start(struct pt_regs *ctx) {
char *cp = NULL;
bpf_usdt_readarg(1, ctx, &cp);
struct { char query[QUERY_MAX]; } data = { };
bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
data.query[0] = 'a'; data.query[1] = 0;
events.perf_submit(ctx, &data, sizeof(data));
return 0;
};
Could you double check on your side?
Yonghong
toggle quoted message
Show quoted text
On 6/5/17 3:27 AM, Tetsuo Handa wrote: Hello.
I noticed that b0f891d129a9b372 ("Force udst ctx->#reg load to be volatile")
broke an USDT probe example shown below.
----------
#!/usr/bin/python
from bcc import BPF, USDT import sys
import ctypes as ct
def usage():
print("USAGE: usdt PID")
exit()
if len(sys.argv) < 1:
usage()
if sys.argv[1][0:1] == "-":
usage()
pid = int(sys.argv[1])
QUERY_MAX = 504
bpf_text = """
#include <uapi/linux/ptrace.h>
#define QUERY_MAX """ + str(QUERY_MAX) + """
BPF_PERF_OUTPUT(events);
int do_start(struct pt_regs *ctx) {
char *cp = NULL;
bpf_usdt_readarg(1, ctx, &cp);
struct { char query[QUERY_MAX]; } data = { };
bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
events.perf_submit(ctx, &data, sizeof(data));
return 0;
};
"""
u = USDT(pid=pid)
u.enable_probe(probe="query__start", fn_name="do_start")
b = BPF(text=bpf_text, usdt_contexts=[u])
class Data(ct.Structure):
_fields_ = [ ("query", ct.c_char * QUERY_MAX) ]
def print_event(cpu, data, size):
event = ct.cast(data, ct.POINTER(Data)).contents
print("%s" % (event.query))
b["events"].open_perf_buffer(print_event, page_cnt=64)
while 1:
b.kprobe_poll()
----------
Since bpf_probe_read() no longer reads PostgreSQL query string
passed to query__start event, nothing is printed out.
(Oh, I forgot to check whether cp != NULL.
Maybe it is bpf_usdt_readarg() which got broken?)
# git bisect log
# bad: [505c110a5f4f48cff1a501f8b83a548ade6a7739] Add a python test for usdt
# good: [aa4543ff2d42a2ca38a52963af9d6d078e48809a] Mention that linux-headers deb must be installed.
git bisect start '505c110a5f4f48cff1a501f8b83a548ade6a7739' 'aa4543ff2d42a2ca38a52963af9d6d078e48809a'
# good: [a934c903583c415ebed70d03a6c15e9b20c52efa] Add linux/sched.h to list of libbpf.c includes
git bisect good a934c903583c415ebed70d03a6c15e9b20c52efa
# bad: [cb8e704ca64de58aab6137faa0b8d6b96f24a257] Merge pull request #1212 from iovisor/yhs_dev
git bisect bad cb8e704ca64de58aab6137faa0b8d6b96f24a257
# bad: [b0f891d129a9b372e7e8af5b951a1b63985afe26] Force udst ctx->#reg load to be volatile
git bisect bad b0f891d129a9b372e7e8af5b951a1b63985afe26
# good: [e7b0ab2dc44b244ef6600630c4e7b16c1f3b123a] Merge pull request #1211 from iovisor/libbpf_c_includes
git bisect good e7b0ab2dc44b244ef6600630c4e7b16c1f3b123a
# first bad commit: [b0f891d129a9b372e7e8af5b951a1b63985afe26] Force udst ctx->#reg load to be volatile
|
|
Tetsuo, I cannot reproduce the issue. The transformation from: dest = ctx->bx; to: dest = *(volatile uint64_t *)&ctx->bx; should be safe. I launched a psql console and did a query: ... yhs=> SELECT order_id FROM order_details; order_id ---------- 6 (1 row) ... On the usdt side, I did not see anything printout. I hacked the code to forcefully emit a meaningful string, but it does not print either. So it looks like the probe function is not called. int do_start(struct pt_regs *ctx) { char *cp = NULL; bpf_usdt_readarg(1, ctx, &cp); struct { char query[QUERY_MAX]; } data = { }; bpf_probe_read(&data.query, sizeof(data.query), (void *) cp); data.query[0] = 'a'; data.query[1] = 0; events.perf_submit(ctx, &data, sizeof(data)); return 0; }; Could you double check on your side? Yonghong On Mon, Jun 5, 2017 at 3:27 AM, Tetsuo Handa via iovisor-dev <iovisor-dev@...> wrote: Hello.
I noticed that b0f891d129a9b372 ("Force udst ctx->#reg load to be volatile")
broke an USDT probe example shown below.
----------
#!/usr/bin/python
from bcc import BPF, USDT import sys
import ctypes as ct
def usage():
print("USAGE: usdt PID")
exit()
if len(sys.argv) < 1:
usage()
if sys.argv[1][0:1] == "-":
usage()
pid = int(sys.argv[1])
QUERY_MAX = 504
bpf_text = """
#include <uapi/linux/ptrace.h>
#define QUERY_MAX """ + str(QUERY_MAX) + """
BPF_PERF_OUTPUT(events);
int do_start(struct pt_regs *ctx) {
char *cp = NULL;
bpf_usdt_readarg(1, ctx, &cp);
struct { char query[QUERY_MAX]; } data = { };
bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
events.perf_submit(ctx, &data, sizeof(data));
return 0;
};
"""
u = USDT(pid=pid)
u.enable_probe(probe="query__start", fn_name="do_start")
b = BPF(text=bpf_text, usdt_contexts=[u])
class Data(ct.Structure):
_fields_ = [ ("query", ct.c_char * QUERY_MAX) ]
def print_event(cpu, data, size):
event = ct.cast(data, ct.POINTER(Data)).contents
print("%s" % (event.query))
b["events"].open_perf_buffer(print_event, page_cnt=64)
while 1:
b.kprobe_poll()
----------
Since bpf_probe_read() no longer reads PostgreSQL query string
passed to query__start event, nothing is printed out.
(Oh, I forgot to check whether cp != NULL.
Maybe it is bpf_usdt_readarg() which got broken?)
# git bisect log
# bad: [505c110a5f4f48cff1a501f8b83a548ade6a7739] Add a python test for usdt
# good: [aa4543ff2d42a2ca38a52963af9d6d078e48809a] Mention that linux-headers deb must be installed.
git bisect start '505c110a5f4f48cff1a501f8b83a548ade6a7739' 'aa4543ff2d42a2ca38a52963af9d6d078e48809a'
# good: [a934c903583c415ebed70d03a6c15e9b20c52efa] Add linux/sched.h to list of libbpf.c includes
git bisect good a934c903583c415ebed70d03a6c15e9b20c52efa
# bad: [cb8e704ca64de58aab6137faa0b8d6b96f24a257] Merge pull request #1212 from iovisor/yhs_dev
git bisect bad cb8e704ca64de58aab6137faa0b8d6b96f24a257
# bad: [b0f891d129a9b372e7e8af5b951a1b63985afe26] Force udst ctx->#reg load to be volatile
git bisect bad b0f891d129a9b372e7e8af5b951a1b63985afe26
# good: [e7b0ab2dc44b244ef6600630c4e7b16c1f3b123a] Merge pull request #1211 from iovisor/libbpf_c_includes
git bisect good e7b0ab2dc44b244ef6600630c4e7b16c1f3b123a
# first bad commit: [b0f891d129a9b372e7e8af5b951a1b63985afe26] Force udst ctx->#reg load to be volatile
_______________________________________________
iovisor-dev mailing list
iovisor-dev@...
https://lists.iovisor.org/mailman/listinfo/iovisor-dev
|
|
Tetsuo Handa <penguin-kernel@...>
Hello.
I changed the hook as below and confirmed that cp == NULL at bpf_probe_read().
That is, it is bpf_usdt_readarg() which got broken.
----------
int do_start(struct pt_regs *ctx) {
char *cp = NULL;
bpf_usdt_readarg(1, ctx, &cp);
struct { char query[QUERY_MAX]; } data = { };
if (cp != NULL)
bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
else
data.query[0] = '!';
events.perf_submit(ctx, &data, sizeof(data));
return 0;
};
----------
If I do
- std::string cptr = tfm::format("*((volatile %s *)dest)", ctype);
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
(i.e. drop only "volatile " part) in that commit like below
----------
diff --git a/src/cc/usdt.cc b/src/cc/usdt.cc
--- a/src/cc/usdt.cc
+++ b/src/cc/usdt.cc
@@ -152,7 +152,7 @@ bool Probe::usdt_getarg(std::ostream &stream) {
for (size_t arg_n = 0; arg_n < arg_count; ++arg_n) {
std::string ctype = largest_arg_type(arg_n);
- std::string cptr("dest");
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
tfm::format(stream,
"static __always_inline int _bpf_readarg_%s_%d("
----------
USDT probe works again as well as build warning shown below goes away.
----------
/virtual/main.c:4:8: warning: incompatible integer to pointer conversion assigning to 'void *' from 'volatile uint64_t' (aka 'volatile unsigned long long') [-Wint-conversion]
dest = *(volatile uint64_t *)&ctx->bx;
^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
----------
|
|
Hi, Tetsuo, You are right. The bug is actually introduced by my last patch. I just focused one aspect of issue and inadvertently introduced another *blocker* bug. I just pushed a patch. Thanks a lot for reporting the issue and testing out the fix. Yonghong On Mon, Jun 5, 2017 at 5:25 PM, Tetsuo Handa <penguin-kernel@...> wrote: Hello.
I changed the hook as below and confirmed that cp == NULL at bpf_probe_read().
That is, it is bpf_usdt_readarg() which got broken.
----------
int do_start(struct pt_regs *ctx) {
char *cp = NULL;
bpf_usdt_readarg(1, ctx, &cp);
struct { char query[QUERY_MAX]; } data = { };
if (cp != NULL)
bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
else
data.query[0] = '!';
events.perf_submit(ctx, &data, sizeof(data));
return 0;
};
----------
If I do
- std::string cptr = tfm::format("*((volatile %s *)dest)", ctype);
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
(i.e. drop only "volatile " part) in that commit like below
----------
diff --git a/src/cc/usdt.cc b/src/cc/usdt.cc
--- a/src/cc/usdt.cc
+++ b/src/cc/usdt.cc
@@ -152,7 +152,7 @@ bool Probe::usdt_getarg(std::ostream &stream) {
for (size_t arg_n = 0; arg_n < arg_count; ++arg_n) {
std::string ctype = largest_arg_type(arg_n);
- std::string cptr("dest");
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
tfm::format(stream,
"static __always_inline int _bpf_readarg_%s_%d("
----------
USDT probe works again as well as build warning shown below goes away.
----------
/virtual/main.c:4:8: warning: incompatible integer to pointer conversion assigning to 'void *' from 'volatile uint64_t' (aka 'volatile unsigned long long') [-Wint-conversion]
dest = *(volatile uint64_t *)&ctx->bx;
^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
----------
|
|
Yonghong, can you send a PR for your branch?
On Tue, Jun 6, 2017 at 12:20 AM, Y Song via iovisor-dev <iovisor-dev@...> wrote: Hi, Tetsuo,
You are right. The bug is actually introduced by my last patch. I just
focused one aspect of issue and inadvertently introduced another
*blocker* bug.
I just pushed a patch. Thanks a lot for reporting the issue and
testing out the fix.
Yonghong
On Mon, Jun 5, 2017 at 5:25 PM, Tetsuo Handa
< penguin-kernel@....ne.jp> wrote:
> Hello.
>
> I changed the hook as below and confirmed that cp == NULL at bpf_probe_read().
> That is, it is bpf_usdt_readarg() which got broken.
>
> ----------
> int do_start(struct pt_regs *ctx) {
> char *cp = NULL;
> bpf_usdt_readarg(1, ctx, &cp);
> struct { char query[QUERY_MAX]; } data = { };
> if (cp != NULL)
> bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
> else
> data.query[0] = '!';
> events.perf_submit(ctx, &data, sizeof(data));
> return 0;
> };
> ----------
>
> If I do
>
> - std::string cptr = tfm::format("*((volatile %s *)dest)", ctype);
> + std::string cptr = tfm::format("*((%s *)dest)", ctype);
>
> (i.e. drop only "volatile " part) in that commit like below
>
> ----------
> diff --git a/src/cc/usdt.cc b/src/cc/usdt.cc
> --- a/src/cc/usdt.cc
> +++ b/src/cc/usdt.cc
> @@ -152,7 +152,7 @@ bool Probe::usdt_getarg(std:: ostream &stream) {
>
> for (size_t arg_n = 0; arg_n < arg_count; ++arg_n) {
> std::string ctype = largest_arg_type(arg_n);
> - std::string cptr("dest");
> + std::string cptr = tfm::format("*((%s *)dest)", ctype);
>
> tfm::format(stream,
> "static __always_inline int _bpf_readarg_%s_%d("
> ----------
>
> USDT probe works again as well as build warning shown below goes away.
>
> ----------
> /virtual/main.c:4:8: warning: incompatible integer to pointer conversion assigning to 'void *' from 'volatile uint64_t' (aka 'volatile unsigned long long') [-Wint-conversion]
> dest = *(volatile uint64_t *)&ctx->bx;
> ^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> ----------
______________________________ _________________
iovisor-dev mailing list
iovisor-dev@...
https://lists.iovisor.org/mailman/listinfo/iovisor-dev
|
|
Also, I would suggest that after that fix, we also update the test to include actually testing for proper values. Probably you can send the values over the perf ring buffer and assert at the end that all of the values are collected properly.
On Tue, Jun 6, 2017 at 8:59 PM, Brenden Blanco <bblanco@...> wrote: Yonghong, can you send a PR for your branch?
|
|
Done. Sorry, I actually pushed the change to my yhs_dev branch last
night, but forgot to generate a pull request ...
toggle quoted message
Show quoted text
On Tue, Jun 6, 2017 at 8:59 PM, Brenden Blanco <bblanco@...> wrote: Yonghong, can you send a PR for your branch?
On Tue, Jun 6, 2017 at 12:20 AM, Y Song via iovisor-dev
<iovisor-dev@...> wrote:
Hi, Tetsuo,
You are right. The bug is actually introduced by my last patch. I just
focused one aspect of issue and inadvertently introduced another
*blocker* bug.
I just pushed a patch. Thanks a lot for reporting the issue and
testing out the fix.
Yonghong
On Mon, Jun 5, 2017 at 5:25 PM, Tetsuo Handa
<penguin-kernel@...> wrote:
Hello.
I changed the hook as below and confirmed that cp == NULL at
bpf_probe_read().
That is, it is bpf_usdt_readarg() which got broken.
----------
int do_start(struct pt_regs *ctx) {
char *cp = NULL;
bpf_usdt_readarg(1, ctx, &cp);
struct { char query[QUERY_MAX]; } data = { };
if (cp != NULL)
bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
else
data.query[0] = '!';
events.perf_submit(ctx, &data, sizeof(data));
return 0;
};
----------
If I do
- std::string cptr = tfm::format("*((volatile %s *)dest)", ctype);
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
(i.e. drop only "volatile " part) in that commit like below
----------
diff --git a/src/cc/usdt.cc b/src/cc/usdt.cc
--- a/src/cc/usdt.cc
+++ b/src/cc/usdt.cc
@@ -152,7 +152,7 @@ bool Probe::usdt_getarg(std::ostream &stream) {
for (size_t arg_n = 0; arg_n < arg_count; ++arg_n) {
std::string ctype = largest_arg_type(arg_n);
- std::string cptr("dest");
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
tfm::format(stream,
"static __always_inline int _bpf_readarg_%s_%d("
----------
USDT probe works again as well as build warning shown below goes away.
----------
/virtual/main.c:4:8: warning: incompatible integer to pointer conversion
assigning to 'void *' from 'volatile uint64_t' (aka 'volatile unsigned long
long') [-Wint-conversion]
dest = *(volatile uint64_t *)&ctx->bx;
^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
---------- _______________________________________________
iovisor-dev mailing list
iovisor-dev@...
https://lists.iovisor.org/mailman/listinfo/iovisor-dev
|
|
100% agree. Will work on a test case soon (maybe next week).
toggle quoted message
Show quoted text
On Tue, Jun 6, 2017 at 9:01 PM, Brenden Blanco <bblanco@...> wrote: Also, I would suggest that after that fix, we also update the test to
include actually testing for proper values. Probably you can send the values
over the perf ring buffer and assert at the end that all of the values are
collected properly.
On Tue, Jun 6, 2017 at 8:59 PM, Brenden Blanco <bblanco@...> wrote:
Yonghong, can you send a PR for your branch?
On Tue, Jun 6, 2017 at 12:20 AM, Y Song via iovisor-dev
<iovisor-dev@...> wrote:
Hi, Tetsuo,
You are right. The bug is actually introduced by my last patch. I just
focused one aspect of issue and inadvertently introduced another
*blocker* bug.
I just pushed a patch. Thanks a lot for reporting the issue and
testing out the fix.
Yonghong
On Mon, Jun 5, 2017 at 5:25 PM, Tetsuo Handa
<penguin-kernel@...> wrote:
Hello.
I changed the hook as below and confirmed that cp == NULL at
bpf_probe_read().
That is, it is bpf_usdt_readarg() which got broken.
----------
int do_start(struct pt_regs *ctx) {
char *cp = NULL;
bpf_usdt_readarg(1, ctx, &cp);
struct { char query[QUERY_MAX]; } data = { };
if (cp != NULL)
bpf_probe_read(&data.query, sizeof(data.query), (void *) cp);
else
data.query[0] = '!';
events.perf_submit(ctx, &data, sizeof(data));
return 0;
};
----------
If I do
- std::string cptr = tfm::format("*((volatile %s *)dest)", ctype);
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
(i.e. drop only "volatile " part) in that commit like below
----------
diff --git a/src/cc/usdt.cc b/src/cc/usdt.cc
--- a/src/cc/usdt.cc
+++ b/src/cc/usdt.cc
@@ -152,7 +152,7 @@ bool Probe::usdt_getarg(std::ostream &stream) {
for (size_t arg_n = 0; arg_n < arg_count; ++arg_n) {
std::string ctype = largest_arg_type(arg_n);
- std::string cptr("dest");
+ std::string cptr = tfm::format("*((%s *)dest)", ctype);
tfm::format(stream,
"static __always_inline int _bpf_readarg_%s_%d("
----------
USDT probe works again as well as build warning shown below goes away.
----------
/virtual/main.c:4:8: warning: incompatible integer to pointer
conversion assigning to 'void *' from 'volatile uint64_t' (aka 'volatile
unsigned long long') [-Wint-conversion]
dest = *(volatile uint64_t *)&ctx->bx;
^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
---------- _______________________________________________
iovisor-dev mailing list
iovisor-dev@...
https://lists.iovisor.org/mailman/listinfo/iovisor-dev
|
|
