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

Fri Feb 1 16:07:19 PST 2019

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.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/llvm-dev/attachments/20190202/d8e83706/attachment.html>