[llvm-xray] llvm-xray cannot log every functions

Hi there,

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.

Here is the program: matrix.c

#include <stdio.h>

void enterData(int firstMatrix[][10], int secondMatrix[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond);
void multiplyMatrices(int firstMatrix[][10], int secondMatrix[][10], int multResult[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond) __attribute__((xray_always_instrument));
void display(int mult[][10], int rowFirst, int columnSecond);

int main()
{
int firstMatrix[10][10], secondMatrix[10][10], mult[10][10], rowFirst, columnFirst, rowSecond, columnSecond, i, j, k;

printf("Enter rows and column for first matrix: ");
scanf("%d %d", &rowFirst, &columnFirst);

printf("Enter rows and column for second matrix: ");
scanf("%d %d", &rowSecond, &columnSecond);

// If colum of first matrix in not equal to row of second matrix, asking user to enter the size of matrix again.
while (columnFirst != rowSecond)
{
printf("Error! column of first matrix not equal to row of second.\n");
printf("Enter rows and column for first matrix: ");
scanf("%d%d", &rowFirst, &columnFirst);
printf("Enter rows and column for second matrix: ");
scanf("%d%d", &rowSecond, &columnSecond);
}

// Function to take matrices data
        enterData(firstMatrix, secondMatrix, rowFirst, columnFirst, rowSecond, columnSecond);

        // Function to multiply two matrices.
        multiplyMatrices(firstMatrix, secondMatrix, mult, rowFirst, columnFirst, rowSecond, columnSecond);

        // Function to display resultant matrix after multiplication.
        display(mult, rowFirst, columnSecond);

return 0;
}

void enterData(int firstMatrix[][10], int secondMatrix[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond)
{
int i, j;
printf("\nEnter elements of matrix 1:\n");
for(i = 0; i < rowFirst; ++i)
{
for(j = 0; j < columnFirst; ++j)
{
printf("Enter elements a%d%d: ", i + 1, j + 1);
scanf("%d", &firstMatrix[i][j]);
}
}

printf("\nEnter elements of matrix 2:\n");
for(i = 0; i < rowSecond; ++i)
{
for(j = 0; j < columnSecond; ++j)
{
printf("Enter elements b%d%d: ", i + 1, j + 1);
scanf("%d", &secondMatrix[i][j]);
}
}
}

void multiplyMatrices(int firstMatrix[][10], int secondMatrix[][10], int mult[][10], int rowFirst, int columnFirst, int rowSecond, int columnSecond)
{
int i, j, k;

// Initializing elements of matrix mult to 0.
for(i = 0; i < rowFirst; ++i)
{
for(j = 0; j < columnSecond; ++j)
{
mult[i][j] = 0;
}
}

// Multiplying matrix firstMatrix and secondMatrix and storing in array mult.
for(i = 0; i < rowFirst; ++i)
{
for(j = 0; j < columnSecond; ++j)
{
for(k=0; k<columnFirst; ++k)
{
mult[i][j] += firstMatrix[i][k] * secondMatrix[k][j];
}
}
}

}

void display(int mult[][10], int rowFirst, int columnSecond)
{
int i, j;
printf("\nOutput Matrix:\n");
for(i = 0; i < rowFirst; ++i)
{
for(j = 0; j < columnSecond; ++j)
{
printf("%d  ", mult[i][j]);
if(j == columnSecond - 1)
printf("\n\n");
}
}
}

Here is the process when I tried to generate the function call:

  1.  I wrote a cmake file to configure it, since later on I would like to use xray on more complicated programs:

         set(CMAKE_C_COMPILER "/home/shangatlab/Desktop/llvm_01_23_19/build/bin/clang")
         set(CMAKE_CXX_COMPILER "/home/shangatlab/Desktop/llvm_01_23_19/build/bin/clang++")

         project("trace test project")
         set(CMAKE_C_FLAGS "-fxray-instrument -fxray-instruction-threshold=1")
         set(CMAKE_CXX_FLAGS "-fxray-instrument -fxray-instruction-threshold=1")

         add_executable(matrix matrix.c
                    )
     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.
     2.  I built it using command "make", and checked with objdump that there is xray_instr_map:

          ./matrix:     file format elf64-x86-64

           Sections:
           Idx Name                 Size      VMA               LMA               File off  Algn
           27 xray_instr_map 00000100  0000000000637ac0  0000000000637ac0  00037ac0  2**0
                                     CONTENTS, ALLOC, LOAD, DATA
     3.  Then I use command "XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic verbosity=2" ./matrix " to generate log file, which works perfectly:

         ==22294==XRay: Log file in 'xray-log.matrix.G42i0m'
          Enter rows and column for first matrix: 1
          1
          Enter rows and column for second matrix: 1
          1

          Enter elements of matrix 1:
          Enter elements a11: 1

          Enter elements of matrix 2:
          Enter elements b11: 1

          Output Matrix:
          1

          ==22294==Cleaned up log for TID: 22294
     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:

          header:
          version:         3
          type:            0
          constant-tsc:    true
          nonstop-tsc:     true
          cycle-frequency: 4000000000
        records:
          - { type: 0, func-id: 1, function: main, cpu: 6, thread: 22294, process: 22294, kind: function-enter, tsc: 38825257620522, data: '' }
          - { type: 0, func-id: 2, function: enterData, cpu: 7, thread: 22294, process: 22294, kind: function-enter, tsc: 38836389634930, data: '' }
          - { type: 0, func-id: 2, function: enterData, cpu: 1, thread: 22294, process: 22294, kind: function-exit, tsc: 38840832349440, data: '' }
          - { type: 0, func-id: 4, function: display, cpu: 1, thread: 22294, process: 22294, kind: function-enter, tsc: 38840832373974, data: '' }
          - { type: 0, func-id: 4, function: display, cpu: 1, thread: 22294, process: 22294, kind: function-exit, tsc: 38840832476724, data: '' }
          - { type: 0, func-id: 1, function: main, cpu: 1, thread: 22294, process: 22294, kind: function-exit, tsc: 38840832485244, data: '' }
        ...

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.

--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:

==22930==XRay: Log file in 'xray-log.matrix.Uybc6L'
Enter rows and column for first matrix: 1
1
Enter rows and column for second matrix: 1
1

Enter elements of matrix 1:
Enter elements a11: 1

Enter elements of matrix 2:
Enter elements b11: 1

Output Matrix:
1

==22930==Skipping buffer for TID: 22930; Offset = 0
==22930==Cleaned up log for TID: 22930

llvm-xray: Failed loading input file 'xray-log.matrix.xEr6h8'.
Cannot read log from 'xray-log.matrix.xEr6h8'

--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:
header:
  version:         3
  type:            0
  constant-tsc:    true
  nonstop-tsc:     true
  cycle-frequency: 4000000000
records:
  - { type: 0, func-id: 1, function: main, cpu: 7, thread: 22687, process: 22687, kind: function-enter, tsc: 40570233068134, data: '' }
  - { type: 0, func-id: 2, function: enterData, cpu: 1, thread: 22687, process: 22687, kind: function-enter, tsc: 40579457699794, data: '' }
  - { type: 0, func-id: 2, function: enterData, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40584365232344, data: '' }
  - { type: 0, func-id: 3, function: multiplyMatrices, cpu: 6, thread: 22687, process: 22687, kind: function-enter, tsc: 40584365247874, data: '' }
  - { type: 0, func-id: 3, function: multiplyMatrices, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40595952636280, data: '' }
  - { type: 0, func-id: 4, function: display, cpu: 6, thread: 22687, process: 22687, kind: function-enter, tsc: 40595952651332, data: '' }
  - { type: 0, func-id: 4, function: display, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40595952712424, data: '' }
  - { type: 0, func-id: 1, function: main, cpu: 6, thread: 22687, process: 22687, kind: function-exit, tsc: 40595952721582, data: '' }

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.

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.

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.

More below:

Dear Dean,

Thank you very much for the quick reply, but I still cannot get the trace log work correctly. I used the command

$XRAY_BASIC_OPTIONS=‘func_duration_threshold=0’ XRAY_OPTIONS=‘patch_premain=true xray_mode=xray-basic verbosity=1’ ./matrix

to generate log.

And used the command

$llvm-xray convert -f yaml -symbolize -instr_map=./matrix xray-log.matrix.EVdnlj

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?

Thank you very much for helping,
Zitong

Are you sure the function isn’t being in-lined into the main function?

You can take some steps to move the definition of the function to a different translation unit (a different .c and which compiles into a different .o) to potentially inhibit the in-lining of the function you want instrumented. As I noted in my previous reply:

"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).”

Hope that helps.

-- Dean