thr3ads.net - llvm dev - [llvm-dev] [llvm-xray] llvm-xray cannot log every functions [Feb 2019]

If this information is useful, please help other people find it:
Share via:

Shang, Zitong via llvm-dev

2019-Feb-02 00:07 UTC

[llvm-dev] [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.

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

Dean Michael Berris via llvm-dev

2019-Feb-02 00:38 UTC

head link

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

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:
> On 2 Feb 2019, at 11:07, Shang, Zitong via llvm-dev <llvm-dev at
lists.llvm.org> wrote:
> 
> 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.
> 
Yes:
https://github.com/llvm/llvm-project/blob/master/compiler-rt/lib/xray/xray_basic_flags.inc

You can set these options in the `XRAY_BASIC_OPTIONS` environment variable.

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

Let me know if this helps, I’d be happy to help debug further.

Cheers

-- Dean

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 195 bytes
Desc: Message signed with OpenPGP
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20190202/f3545150/attachment.sig>

Shang, Zitong via llvm-dev

2019-Feb-02 01:01 UTC

head link

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

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
________________________________
From: Dean Michael Berris <dean.berris at gmail.com>
Sent: Friday, February 1, 2019 6:38 PM
To: Shang, Zitong
Cc: llvm-dev at lists.llvm.org
Subject: Re: [llvm-dev] [llvm-xray] llvm-xray cannot log every functions

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:
> On 2 Feb 2019, at 11:07, Shang, Zitong via llvm-dev <llvm-dev at
lists.llvm.org> wrote:
>
> 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.
>
Yes:
https://github.com/llvm/llvm-project/blob/master/compiler-rt/lib/xray/xray_basic_flags.inc

You can set these options in the `XRAY_BASIC_OPTIONS` environment variable.

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

Let me know if this helps, I’d be happy to help debug further.

Cheers

-- Dean

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

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

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

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

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