Bpftrace: Mixing asynchrous and synchronous actions produces unpredictable results

[danobi]

$ cat ~/scratch/bpftrace/bugs/increment.bt
profile:ms:10 {                                                                                                                                                                                                                                                                           
  @times++;                                                                                                                                                                                                                                                                               
}                                                                                                                                                                                                                                                                                         

interval:s:2 {                                                                                                                                                                                                                                                                            
  print(@times);                                                                                                                                                                                                                                                                          
  @times = 0;                                                                                                                                                                                                                                                                             
}                 

$ sudo ./build/src/bpftrace ~/scratch/bpftrace/bugs/increment.bt
[sudo] password for dlxu: 
Attaching 2 probes...
@times: 0

@times: 0

@times: 0

^C

@times: 88

Switching @times = 0 to clear(@times) works, though.

[danobi]

My theory is:

1. the bpf prog queues up a print
2. the bpf prog sets the value to 0
3. userspace processes the print but it's already been set to 0

2 should happen after 3 but the queue introduces a delay. clear() works because it's implemented in userspace and userspace serializes it.

This is a real tricky issue because we need some kind of fencing mechanism to either pause bpf prog execution or make all the variables be set in userspace. However, the latter option creates additional read-after-write hazards inside the bpf prog.

[ajor]

Yeah this is just because that script is mixing synchronous and asynchronous actions. Either entirely asynchronous (print(@times); clear(@times)), or entirely synchronous (printf("%d\n", @times); @times = 0;) would also work (with the latter being a lot faster).

I don't think this is something we can fix - people just need to be careful about using asynchronous actions.

EDIT: printf is actually asynchronous too, but the values passed to it are calculated in kernel before being put on the perf buffer.

[ajor]

Maybe the docs should be updated to make the asynchronous stuff clearer

[danobi]

I don't think this is something we can fix - people just need to be careful about using asynchronous actions.

Do you think this is something we should prevent? We could analyze the AST and check for potential hazards.

I don't think this is something we can fix

I wonder if we could precompute print()s as well. Or maybe even create 2x of each map -- one for computation, one to store data to be printed.

Ultimately, I think this is a pretty big gotcha and should be directly addressed. After speaking with users over the last week, I don't think this is a problem that can be adequately addressed with documentation.

[ajor]

Yeah guess you're right about needing to do something about it.

The problem functions would be print, clear and zero. They can't be done in the kernel since they iterate over each key in a map and loops aren't allowed. It's possible that kernel changes could make clear and zero work, but I'm not sure about print. Plus the kernel people probably wouldn't want to do it.

An easy option would be to hide these three functions behind a new command line flag, like we've done with --unsafe. Something like --async? It would at least make people think before using them.

Could alternatively make users mark probes as async to use those functions inside them. This would let them be used in some probes while still alerting if they're used where they shouldn't be.

e.g.

kprobe:foo
{
  @x[tid] = 1;
  printf("%d\n", @x[tid]);   // OK
  print(@x);                 // NOPE - probe not async
}
async END
{
  clear(@x);                 // OK - probe is async
}

Just throwing ideas out, not saying this is necessarily a good solution.

[danobi]

Let me ask some of the kernel devs if there's any ways to be clever or any acceptable features we can add into the kernel.

Failing that, I think that we should strive to keep the solution to this as forward compatible as possible. I know Alexei has been trying to add loop verification to the verifier for a long time now. If that actually solves our problem, it'd be unfortunate to have to maintain async attributes or --async flags.

One option that might work is some kind of suppressible warning message about possible hazards.

[danobi]

Apparently it should be possible to iterate over the contents of a map. I'll try to make a small test program to test it out.

[brendangregg]

What problem are you solving? Asynchronous actions are known and documented. If you start changing these, a LOT will break.

Consider the following common construct to print per-interval stats:

interval:s:1
{
    print(@stats);
    clear(@stats);
}

If you started by making clear() a synchronous action, then this -- and all the tools that use this -- would then be broken. clear() would happen faster than user-space could run print(), and print() would always print nothing.

How would you make print() synchronous? You could take a snapshot of the entire map, and user-space prints the snapshot, but maps can get big, and this can be run from arbitrary probe context. What problem is this solving? This would be a major change, and so far I've written a ton of bpftrace without needing it.

[ajor]

Yeah if we made one of the three (print, clear, zero) synchronous we’d have to do it for them all. That would be compatible with current scripts and would mean there were no caveats to using them alongside the other (synchronous) builtin functions like printf and delete.

---

From: Brendan Gregg [e-mail]
Sent: Friday, June 14, 2019 3:16 am
To: iovisor/bpftrace
Cc: Alastair Robertson; Comment
Subject: Re: [iovisor/bpftrace] Mixing asynchrous and synchronous actions produces unpredictable results (#718)

What problem are you solving? Asynchronous actions are known and documented. If you start changing these, a LOT will break.

Consider the following common construct to print per-interval stats:

interval:s:1{ print(@stats); clear(@stats);}

If you started by making clear() a synchronous action, then this -- and all the tools that use this -- would then be broken. clear() would happen faster than user-space could run print(), and print() would always print nothing.

How would you make print() synchronous? You could take a snapshot of the entire map, and user-space prints the snapshot, but maps can get big, and this can be run from arbitrary probe context. What problem is this solving? This would be a major change, and so far I've written a ton of bpftrace without needing it.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHubhttps://github.com/iovisor/bpftrace/issues/718?email_source=notifications&email_token=AAHV6VU7OCVM7AWLOCQHCPLP2L5ONA5CNFSM4HTFLDC2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODXVQRHA#issuecomment-501942428, or mute the threadhttps://github.com/notifications/unsubscribe-auth/AAHV6VV7FUAU5QJM6F7IBJDP2L5ONANCNFSM4HTFLDCQ.