Re: [Qemu-devel] basic block tracing question
On 16 March 2016 at 20:28, Tim Newsham wrote: > Hi, I would like to create an accurate trace of basic blocks that get > executed. I'm interested in a trace of what a CPU would execute, and not > for the purposes of studying qemu itself. > > I'm currently emitting trace data from cpu_tb_exec > https://github.com/qemu/qemu/blob/master/cpu-exec.c#L136 > by printing out the env->eip (x86_64 only). This seems to be roughly > the right place -- there's already cpu tracing in this function. > I do notice that some basic blocks get printed twice here though, and > I tracked it down to basic blocks being rescheduled if execution returns > with TB_EXIT_* flags set > https://github.com/qemu/qemu/blob/master/cpu-exec.c#L163 > So I capture the PC before execution and only emit them if this is > not the case, after execution. This gets rid of the duplicate edges in > the trace, but there is still one problem left that I don't understand! If you only emit tracing information after the TB has executed and returned then you will miss the case where we execute half a TB and take an exception (eg load/store that page faulted, or system call), because in that case we'll longjmp() out of the generated code. That's one of the reasons why the tracing we have in upstream traces before TB execution. > Sometimes, when running the same program twice in a situation that > should give the exact same trace, I see differences: > > exec 8100450a > exec 81091130 > -exec 812f2930 > + basic block ff812f2930 returned with flag 3, setting pc to > 812f285d > +exec 812f285d > exec 812f293d > exec 81091142 > > In this case the basic block wasn't merely restarted. The PC was updated > to a different value after the next_tb had the TB_EXIT_REQUESTED flag set. > The particular basic block in question at 812f2930 ends with a callq > to 0x812f2850 and then falls through to 0x812f293d. So I > would > expect to see the "..2930" and "..293d" in the trace, but not the "..285d" > in > the trace, unless it was just continuing mid-basic block after the exit? Firstly, are you running with -d nochain to disable QEMU's chaining of TBs? (If not, then when we chain TBs together you'll only get exec tracing for the first one, which is a good way to get confused. The default tracing will tell you when we chain TBs together so you can sort of unconfuse yourself, but it's easier to just turn it off if you care about the TB logging.) > What exactly is going on here. What is the purpose of the TB_EXIT_REQUESTED > here? TB_EXIT_REQUESTED means "something asynchronous to execution requested that we stop executing code". Usually this means "pending interrupt", though some other things can cause it too. At the start of every TB we check a flag to see if we need to stop; if the flag is set then we drop out of generated code with the TB_EXIT_REQUESTED status (and the main loop then takes care of identifying pending interrupts or whatever it was that needed our attention.) If you haven't disabled chaining of TBs, then we might drop out before executing a chained TB; in this case we need to fix up the CPU state to correctly represent the fact that we executed the first TB in the chain but not the second one (or whatever). This requires (among other things) setting the PC to the guest address of the start of the TB we didn't execute. (We may also exit mid-TB if icount is enabled and we're doing exact instruction counting; in that case if we've said "execute 50 instructions" then we have to stop in the middle of a TB when we hit the 50 instruction mark. icount isn't the default though so unless your QEMU command line is enabling it then you won't be hitting that; this is flag 2 (TB_EXIT_ICOUNT_EXPIRED).) thanks -- PMM
[Qemu-devel] basic block tracing question
Hi, I would like to create an accurate trace of basic blocks that get executed. I'm interested in a trace of what a CPU would execute, and not for the purposes of studying qemu itself. I'm currently emitting trace data from cpu_tb_exec https://github.com/qemu/qemu/blob/master/cpu-exec.c#L136 by printing out the env->eip (x86_64 only). This seems to be roughly the right place -- there's already cpu tracing in this function. I do notice that some basic blocks get printed twice here though, and I tracked it down to basic blocks being rescheduled if execution returns with TB_EXIT_* flags set https://github.com/qemu/qemu/blob/master/cpu-exec.c#L163 So I capture the PC before execution and only emit them if this is not the case, after execution. This gets rid of the duplicate edges in the trace, but there is still one problem left that I don't understand! Sometimes, when running the same program twice in a situation that should give the exact same trace, I see differences: exec 8100450a exec 81091130 -exec 812f2930 + basic block ff812f2930 returned with flag 3, setting pc to 812f285d +exec 812f285d exec 812f293d exec 81091142 In this case the basic block wasn't merely restarted. The PC was updated to a different value after the next_tb had the TB_EXIT_REQUESTED flag set. The particular basic block in question at 812f2930 ends with a callq to 0x812f2850 and then falls through to 0x812f293d. So I would expect to see the "..2930" and "..293d" in the trace, but not the "..285d" in the trace, unless it was just continuing mid-basic block after the exit? What exactly is going on here. What is the purpose of the TB_EXIT_REQUESTED here? What is causing execution to resume at "...285d" afterwards? Is there a simple way to filter out any extraneous basic blocks that get started midpoint (if that is the case) and keep the true basic block starts? Thank you in advance for any insights. -- Tim Newsham | www.thenewsh.com/~newsham | @newshtwit | thenewsh.blogspot.com
Re: [Qemu-devel] basic block tracing question
On 16 March 2016 at 21:06, Tim Newsham wrote: > What happens when the basic block gets interrupted mid execution > and restarted? Will execution jump to the middle of the translated > basic block, or will a new translation be performed starting at the > midpoint? We translate afresh starting at the midpoint (assuming we do restart there at all, of course -- the OS exception handler might kill the process instead). thanks -- PMM
Re: [Qemu-devel] basic block tracing question
On Wed, Mar 16, 2016 at 10:52 AM, Peter Maydell wrote: > > If you only emit tracing information after the TB has executed and > returned then you will miss the case where we execute half a TB > and take an exception (eg load/store that page faulted, or system call), > because in that case we'll longjmp() out of the generated code. That's > one of the reasons why the tracing we have in upstream traces before > TB execution. > What happens when the basic block gets interrupted mid execution and restarted? Will execution jump to the middle of the translated basic block, or will a new translation be performed starting at the midpoint? Firstly, are you running with -d nochain to disable QEMU's chaining > of TBs? (If not, then when we chain TBs together you'll only get > exec tracing for the first one, which is a good way to get confused. > The default tracing will tell you when we chain TBs together so you > can sort of unconfuse yourself, but it's easier to just turn it off > if you care about the TB logging.) > I was not using "-d nochain". Thank you! > thanks > -- PMM > -- Tim Newsham | www.thenewsh.com/~newsham | @newshtwit | thenewsh.blogspot.com