<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=Windows-1252">
<style type="text/css" style="display:none;"><!-- P {margin-top:0;margin-bottom:0;} --></style>
</head>
<body dir="ltr">
<div id="divtagdefaultwrapper" style="font-size:12pt;color:#000000;font-family:Calibri,Helvetica,sans-serif;" dir="ltr">
<p style="margin-top:0;margin-bottom:0">Dear Dean,</p>
<p style="margin-top:0;margin-bottom:0"><br>
</p>
<p style="margin-top:0;margin-bottom:0">Thank you very much for the quick reply, but I still cannot get the trace log work correctly. I used the command </p>
<br>
<span>$XRAY_BASIC_OPTIONS='func_duration_threshold=0' XRAY_OPTIONS='patch_premain=true xray_mode=xray-basic verbosity=1' ./matrix </span>
<div><br>
</div>
<div><span></span>to generate log.</div>
<div><br>
</div>
<div>And used the command</div>
<div><span><br>
</span></div>
<div><span>$llvm-xray convert -f yaml -symbolize -instr_map=./matrix xray-log.matrix.EVdnlj</span></div>
<div><span><br>
</span></div>
<div><span>to let the log become readable. However, it still does not show up the multiply function that I defined in the program. Is there anything else that I did wrongly?</span></div>
<div><span><br>
</span></div>
<div><span>Thank you very much for helping,</span></div>
<div><span style="font-size: 12pt;">Zitong </span><br>
</div>
<div>
<div style="color: rgb(0, 0, 0);">
<hr style="display:inline-block;width:98%" tabindex="-1">
<div id="divRplyFwdMsg" dir="ltr"><font face="Calibri, sans-serif" style="font-size:11pt" color="#000000"><b>From:</b> Dean Michael Berris <dean.berris@gmail.com><br>
<b>Sent:</b> Friday, February 1, 2019 6:38 PM<br>
<b>To:</b> Shang, Zitong<br>
<b>Cc:</b> llvm-dev@lists.llvm.org<br>
<b>Subject:</b> Re: [llvm-dev] [llvm-xray] llvm-xray cannot log every functions</font>
<div> </div>
</div>
<div class="BodyFragment"><font size="2"><span style="font-size:11pt;">
<div class="PlainText">Hi — I’m really sorry about the experience you’re having with this. I think there’s a bug here in that the documentation isn’t as clear as it is given the recent changes in the “basic” mode for XRay.<br>
<br>
The TL;DR: Try setting `XRAY_BASIC_OPTIONS=func_duration_threshold=0` in your environment in addition to the `XRAY_OPTIONS` environment variable to avoid the in-memory filtering of function durations.<br>
<br>
More below:<br>
<br>
> On 2 Feb 2019, at 11:07, Shang, Zitong via llvm-dev <llvm-dev@lists.llvm.org> wrote:<br>
> <br>
> Hi there,<br>
> <br>
> <br>
> I have a problem using the function call tracing tools that is designed in llvm tools set. My aim is to record every function call that a program makes when it run. However, for whatever reason, a simple matrix multiply c program that I wrote cannot record
all the function calls that happened when the program run.<br>
> <br>
> <br>
> Here is the program: matrix.c<br>
> <br>
> #include <stdio.h><br>
> <br>
> void enterData(int firstMatrix[][10], int secondMatrix[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond);<br>
> void multiplyMatrices(int firstMatrix[][10], int secondMatrix[][10], int multResult[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond) __attribute__((xray_always_instrument));<br>
> void display(int mult[][10], int rowFirst, int columnSecond);<br>
> <br>
> int main()<br>
> {<br>
> int firstMatrix[10][10], secondMatrix[10][10], mult[10][10], rowFirst, columnFirst, rowSecond, columnSecond, i, j, k;<br>
> <br>
> printf("Enter rows and column for first matrix: ");<br>
> scanf("%d %d", &rowFirst, &columnFirst);<br>
> <br>
> printf("Enter rows and column for second matrix: ");<br>
> scanf("%d %d", &rowSecond, &columnSecond);<br>
> <br>
> // If colum of first matrix in not equal to row of second matrix, asking user to enter the size of matrix again.<br>
> while (columnFirst != rowSecond)<br>
> {<br>
> printf("Error! column of first matrix not equal to row of second.\n");<br>
> printf("Enter rows and column for first matrix: ");<br>
> scanf("%d%d", &rowFirst, &columnFirst);<br>
> printf("Enter rows and column for second matrix: ");<br>
> scanf("%d%d", &rowSecond, &columnSecond);<br>
> }<br>
> <br>
> // Function to take matrices data<br>
> enterData(firstMatrix, secondMatrix, rowFirst, columnFirst, rowSecond, columnSecond);<br>
> <br>
> // Function to multiply two matrices.<br>
> multiplyMatrices(firstMatrix, secondMatrix, mult, rowFirst, columnFirst, rowSecond, columnSecond);<br>
> <br>
> // Function to display resultant matrix after multiplication.<br>
> display(mult, rowFirst, columnSecond);<br>
> <br>
> return 0;<br>
> }<br>
> <br>
> void enterData(int firstMatrix[][10], int secondMatrix[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond)<br>
> {<br>
> int i, j;<br>
> printf("\nEnter elements of matrix 1:\n");<br>
> for(i = 0; i < rowFirst; ++i)<br>
> {<br>
> for(j = 0; j < columnFirst; ++j)<br>
> {<br>
> printf("Enter elements a%d%d: ", i + 1, j + 1);<br>
> scanf("%d", &firstMatrix[i][j]);<br>
> }<br>
> }<br>
> <br>
> printf("\nEnter elements of matrix 2:\n");<br>
> for(i = 0; i < rowSecond; ++i)<br>
> {<br>
> for(j = 0; j < columnSecond; ++j)<br>
> {<br>
> printf("Enter elements b%d%d: ", i + 1, j + 1);<br>
> scanf("%d", &secondMatrix[i][j]);<br>
> }<br>
> }<br>
> }<br>
> <br>
> void multiplyMatrices(int firstMatrix[][10], int secondMatrix[][10], int mult[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond)<br>
> {<br>
> int i, j, k;<br>
> <br>
> // Initializing elements of matrix mult to 0.<br>
> for(i = 0; i < rowFirst; ++i)<br>
> {<br>
> for(j = 0; j < columnSecond; ++j)<br>
> {<br>
> mult[i][j] = 0;<br>
> }<br>
> }<br>
> <br>
> // Multiplying matrix firstMatrix and secondMatrix and storing in array mult.<br>
> for(i = 0; i < rowFirst; ++i)<br>
> {<br>
> for(j = 0; j < columnSecond; ++j)<br>
> {<br>
> for(k=0; k<columnFirst; ++k)<br>
> {<br>
> mult[i][j] += firstMatrix[i][k] * secondMatrix[k][j];<br>
> }<br>
> }<br>
> }<br>
> <br>
> }<br>
> <br>
> void display(int mult[][10], int rowFirst, int columnSecond)<br>
> {<br>
> int i, j;<br>
> printf("\nOutput Matrix:\n");<br>
> for(i = 0; i < rowFirst; ++i)<br>
> {<br>
> for(j = 0; j < columnSecond; ++j)<br>
> {<br>
> printf("%d ", mult[i][j]);<br>
> if(j == columnSecond - 1)<br>
> printf("\n\n");<br>
> }<br>
> }<br>
> }<br>
> <br>
> Here is the process when I tried to generate the function call:<br>
> <br>
> 1. I wrote a cmake file to configure it, since later on I would like to use xray on more complicated programs:<br>
> <br>
> <br>
> <br>
> set(CMAKE_C_COMPILER "/home/shangatlab/Desktop/llvm_01_23_19/build/bin/clang")<br>
> set(CMAKE_CXX_COMPILER "/home/shangatlab/Desktop/llvm_01_23_19/build/bin/clang++")<br>
> <br>
> project("trace test project")<br>
> set(CMAKE_C_FLAGS "-fxray-instrument -fxray-instruction-threshold=1")<br>
> set(CMAKE_CXX_FLAGS "-fxray-instrument -fxray-instruction-threshold=1")<br>
> <br>
> add_executable(matrix matrix.c<br>
> )<br>
> As the official document said, I put on instruction threshold flag to 1, and is using the most recently released version of clang-9 that is built from source together with compiler-rt built with source.<br>
> 2. I built it using command "make", and checked with objdump that there is xray_instr_map:<br>
> <br>
> ./matrix: file format elf64-x86-64<br>
> <br>
> Sections:<br>
> Idx Name Size VMA LMA File off Algn<br>
> 27 xray_instr_map 00000100 0000000000637ac0 0000000000637ac0 00037ac0 2**0<br>
> CONTENTS, ALLOC, LOAD, DATA<br>
> 3. Then I use command "XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic verbosity=2" ./matrix " to generate log file, which works perfectly:<br>
> <br>
> ==22294==XRay: Log file in 'xray-log.matrix.G42i0m'<br>
> Enter rows and column for first matrix: 1<br>
> 1<br>
> Enter rows and column for second matrix: 1<br>
> 1<br>
> <br>
> Enter elements of matrix 1:<br>
> Enter elements a11: 1<br>
> <br>
> Enter elements of matrix 2:<br>
> Enter elements b11: 1<br>
> <br>
> Output Matrix:<br>
> 1<br>
> <br>
> ==22294==Cleaned up log for TID: 22294<br>
> 4. Then I used the llvm-xray convert tool to make the trace log readable, by "llvm-xray convert -f yaml -symbolize -instr_map=./matrix xray-log.matrix.G42i0m". However, it never shows the log trace of the function "multiplyMatrices" which is definitely
called when the program run:<br>
> <br>
> header:<br>
> version: 3<br>
> type: 0<br>
> constant-tsc: true<br>
> nonstop-tsc: true<br>
> cycle-frequency: 4000000000<br>
> records:<br>
> - { type: 0, func-id: 1, function: main, cpu: 6, thread: 22294, process: 22294, kind: function-enter, tsc: 38825257620522, data: '' }<br>
> - { type: 0, func-id: 2, function: enterData, cpu: 7, thread: 22294, process: 22294, kind: function-enter, tsc: 38836389634930, data: '' }<br>
> - { type: 0, func-id: 2, function: enterData, cpu: 1, thread: 22294, process: 22294, kind: function-exit, tsc: 38840832349440, data: '' }<br>
> - { type: 0, func-id: 4, function: display, cpu: 1, thread: 22294, process: 22294, kind: function-enter, tsc: 38840832373974, data: '' }<br>
> - { type: 0, func-id: 4, function: display, cpu: 1, thread: 22294, process: 22294, kind: function-exit, tsc: 38840832476724, data: '' }<br>
> - { type: 0, func-id: 1, function: main, cpu: 1, thread: 22294, process: 22294, kind: function-exit, tsc: 38840832485244, data: '' }<br>
> ...<br>
> <br>
> <br>
> All I got is three other function traces, main enterData and display, but we can see from the function id that multiplyMatrices is definitely occupying function id 3. For any reason, it could not be printed out.<br>
> <br>
> <br>
> --I have tried to change the XRAY_OPTIONS patch_premain=false, as suggested in the document that this is the right thing to do when you want to record every function. However, I encounter a question like this:<br>
> <br>
> ==22930==XRay: Log file in 'xray-log.matrix.Uybc6L'<br>
> Enter rows and column for first matrix: 1<br>
> 1<br>
> Enter rows and column for second matrix: 1<br>
> 1<br>
> <br>
> Enter elements of matrix 1:<br>
> Enter elements a11: 1<br>
> <br>
> Enter elements of matrix 2:<br>
> Enter elements b11: 1<br>
> <br>
> Output Matrix:<br>
> 1<br>
> <br>
> ==22930==Skipping buffer for TID: 22930; Offset = 0<br>
> ==22930==Cleaned up log for TID: 22930<br>
> <br>
> llvm-xray: Failed loading input file 'xray-log.matrix.xEr6h8'.<br>
> Cannot read log from 'xray-log.matrix.xEr6h8'<br>
> <br>
> --I have also tried to put some redundant code in multiplyMatrices function like scanf & printf, which are the only difference between this function and other two function enter and display data, that there is no interact with console in multiply function.
With the same command lines being used, it printed out all the real function calls trace:<br>
> header:<br>
> version: 3<br>
> type: 0<br>
> constant-tsc: true<br>
> nonstop-tsc: true<br>
> cycle-frequency: 4000000000<br>
> records:<br>
> - { type: 0, func-id: 1, function: main, cpu: 7, thread: 22687, process: 22687, kind: function-enter, tsc: 40570233068134, data: '' }<br>
> - { type: 0, func-id: 2, function: enterData, cpu: 1, thread: 22687, process: 22687, kind: function-enter, tsc: 40579457699794, data: '' }<br>
> - { type: 0, func-id: 2, function: enterData, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40584365232344, data: '' }<br>
> - { type: 0, func-id: 3, function: multiplyMatrices, cpu: 6, thread: 22687, process: 22687, kind: function-enter, tsc: 40584365247874, data: '' }<br>
> - { type: 0, func-id: 3, function: multiplyMatrices, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40595952636280, data: '' }<br>
> - { type: 0, func-id: 4, function: display, cpu: 6, thread: 22687, process: 22687, kind: function-enter, tsc: 40595952651332, data: '' }<br>
> - { type: 0, func-id: 4, function: display, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40595952712424, data: '' }<br>
> - { type: 0, func-id: 1, function: main, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40595952721582, data: '' }<br>
> <br>
> <br>
> I am really desperate about this. I also used llvm-xray extract command and find out that all functions are instrumented correctly. Does anyone has any idea why this will happen? If it is because the latency of the multiply function is too small, so it cannot
get properly logged, is there any way to fix that? Thanks in advance.<br>
> <br>
<br>
Yes: <a href="https://github.com/llvm/llvm-project/blob/master/compiler-rt/lib/xray/xray_basic_flags.inc" id="LPlnk826526" class="OWAAutoLink" previewremoved="true">
https://github.com/llvm/llvm-project/blob/master/compiler-rt/lib/xray/xray_basic_flags.inc</a><br>
<br>
You can set these options in the `XRAY_BASIC_OPTIONS` environment variable.<br>
<br>
The other potential explanation here is function inlining — if it just so happens that the function is inlined, it could still be marked "instrumented” in the instrumentation map, but only because there could be a “comdat” version of the function just-in-case
the address of the function gets taken. Instrumented functions that are inlined don’t get the instrumentation, because the inlining happens at the LLVM IR level rather than the machine code level (where XRay instrumentation gets added).<br>
<br>
Let me know if this helps, I’d be happy to help debug further.<br>
<br>
Cheers<br>
<br>
-- Dean<br>
<br>
</div>
</span></font></div>
</div>
</div>
</div>
</body>
</html>