XRay FDR number of function enter and exits are not consistent

[llvmbot]

Bugzilla Link	37930
Version	unspecified
OS	Linux
Reporter	LLVM Bugzilla Contributor

Extended Description

Hello,

I encountered a problem where xray generates logs where the number of function enters increases more than the function exits the longer the program is running. I am testing xray on nginx version 1.12 to see what XRay reports on the function calls and returns. I am running on 16.04.1-Ubuntu x86_64 machine. I modified the nginx source to produce xray logs and compiled nginx with –fxray-instrument –fxray-instruction-threshold=1. I ran nginx with XRAY_OPTIONS=”patch_premain=true xray_mode=xray-fdr verbosity=1”. I ran nginx with xray enabled multiple times, each time with a different amount of requests before exiting nginx and I noticed that the total difference between the function-enter/function-exits increases when I send more total requests. Then, the stack would overflow if nginx ran for too long, which should not occur with nginx.
I have three test cases where I send 10, 50 and 100 requests to nginx using wget localhost:port. When I count the number of function enters and exits from the log (llvm-xray convert –f yaml –symbolize –instr_map=./nginx (xray log)
10 requests:
I get 385 of function-enters and 338 function-exits
50_request:
I get 1691 function-enters and 1484 function-exits.
100_request file:
I get 4403 function-enters and 2991 function-exits.

This is unusual as one would expect the stack to go back to its original state (nginx should return to its original state) when there are no more requests to handle. Thus, the difference between the function-enters and function-exits should stay consistent. Is it possible that xray is reporting extra functions or not catching certain returns?

I can send the generated xray log files if that helps. Let me know if you want more details on how xray, nginx were built.

Thanks,
Henry

[llvmbot]

Thanks for the bug report, Henry!

I have some explanations for the potential differences in function entry/exits, which we have already known about in the past. Some of these are:

• If code is using setjmp/longjmp for control flow, this is going to be invisible to XRay today. These can explain the difference between the function entry/exit numbers. This is equivalent to manual stack manipulation on function return pointers which will be transparent to XRay.

• If code is using exceptions, we cannot track which functions have their stacks unwound. This would be one of those kinds of exits that don't really exit functions as far as static code is concerned. XRay doesn't support exception handling/unwind tracking yet.

We could have a bug in the runtime, wherein we can overflow the stack if the instrumentation handlers themselves are XRay-instrumented as well. That would not be ideal, but we do know that the XRay trampolines will require ~200 bytes of stack space to effectively perform stashing and un-stashing of the registers.

Do you know which functions don't have matching enter/exits?

Just to be clear, is nginx itself crashing when built with XRay due to a stack overflow? If it is, then that's a real problem. The only way I can see this happening is if the dispatching thread/process uses setjmp/longjmp in signal handlers that run in the middle of an XRay-instrumented function.

If this is the case, you may want to wrap that dispatch code in __attribute__((xray_never_instrument)) to ensure that the specific function never gets instrumented by XRay.

One helpful thing might be if you can use the Chrome Trace Viewer visualisation of the FDR Mode implementation to see what might be happening. You can do:

llvm-xray convert -symbolize -instr_map=./nginx -output-format=trace_event xray-log.clang-6.0.XXXXXX | gzip > nginx.txt.gz

Then load that through chrome://tracing which should give a useful visualisation of what XRay thinks is happening.

[llvmbot]

Also, tail exits aren't spelled 'function-exits', so you might be under-counting the exits.

Do you have an update on this issue?

[llvmbot]

Sorry for not responding earlier.

The code did not have setjmp/longjmps or exceptions.

I tried the other methods, and it seems like there weren't any problems with the output

Apparently, I got the wrong number of exits as you mentioned in the previous post.

However, there is a different problem (that is related) that I encountered.

Since nginx calls fork(), 2 xray logs are generated when nginx finishes. I have tried to put both of these logs into chrome's tracing as you mentioned below, but one produces a bar that has "381 (Did not finish)" and the other one has a stack trace.

---

While importing:
Error: Could not find an importer for the provided eventData.
at addImportStage (chrome://tracing/tracing.js:1288:64)
at Task.run (chrome://tracing/tracing.js:2197:95)
at runAnother (chrome://tracing/tracing.js:2200:371)
at runTask (chrome://tracing/tracing.js:2176:57)
at processIdleWork (chrome://tracing/tracing.js:2181:116)
at window.requestIdleCallback.timeout (chrome://tracing/tracing.js:2174:81)

Let me know if you want to look at the traces.

Thanks,
Henry