test failures in ARM32 raspbian

[honggyukim]

I've run tests in ARM32 raspbian and here are the failed tests.

Start 234 tests with 1 worker
Test case                 pg             finstrument-fu
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os
012 demangle            : NG NG NG NG NG NG NG NG NG NG
043 full_demangle       : NG NG NG NG NG NG NG NG NG NG
048 malloc_impl         : TM TM TM TM TM TM TM TM TM TM    # Fixed
052 nested_func         : OK OK OK OK OK NG NG NG NG NG
062 arg_char            : NG NG NG NG NG SK SK SK SK SK    # Fixed
065 arg_order           : NG NG NG NG NG SK SK SK SK SK
082 arg_many            : NG NG NG NG NG SK SK SK SK SK
083 arg_float           : NG NG NG NG NG SK SK SK SK SK
084 arg_mixed           : NG NG NG NG NG SK SK SK SK SK
085 arg_reg             : NG NG NG NG NG SK SK SK SK SK
086 arg_stack           : NG NG NG NG NG SK SK SK SK SK
087 arg_variadic        : NG NG NG NG NG SK SK SK SK SK
117 time_range          : NG NG NG NG NG NG NG NG NG NG
119 malloc_hook         : TM TM TM TM TM TM TM TM TM TM    # Fixed
120 malloc_tsd          : TM TM TM TM TM TM TM TM TM TM    # Fixed
121 malloc_fork         : TM TM TM TM TM TM TM TM TM TM    # Fixed
124 exception           : NG NG NG NG NG NG NG NG NG NG
125 report_range        : NG NG NG NG NG NG NG NG NG NG
131 lib_dlopen          : NZ NZ NZ NZ NZ OK OK OK OK OK
135 trigger_time2       : OK OK OK OK OK OK NG NG OK NG
151 recv_runcmd         : NG NG NG NG NG NG NG NG NG NG
152 read_proc_statm     : TM TM TM TM TM TM TM TM TM TM
153 read_page_fault     : TM TM TM TM TM TM TM TM TM TM
156 trigger_finish2     : TM TM TM TM TM OK TM TM OK TM
159 report_diff_policy2 : NG NG NG NG NG NG NG NG NG NG
163 event_sched         : OK OK OK OK OK OK OK OK OK NG
166 dump_sched          : OK NG OK OK OK OK OK OK OK OK
167 recv_sched          : OK OK NZ OK OK OK OK OK OK OK
172 trigger_filter      : OK TM OK OK OK TM TM TM OK OK
173 trigger_args        : TM TM TM TM TM SK SK SK SK SK
175 filter_time_read    : TM TM TM TM TM TM TM TM TM TM
176 arg_fptr            : TM OK TM TM OK TM TM OK TM TM
178 arg_auto1           : TM OK OK TM TM TM TM OK TM OK
179 arg_auto2           : TM TM TM TM TM TM TM TM TM TM
180 arg_auto3           : TM TM TM TM TM TM TM TM TM TM
184 arg_enum            : TM TM TM TM TM TM TM TM TM TM
185 exception2          : TM TM TM TM TM TM TM TM TM TM
186 exception3          : TM TM TM TM TM TM TM TM TM TM
190 trigger_autoargs    : OK TM TM TM TM TM TM TM OK TM
191 posix_spawn         : TM TM TM TM TM TM TM TM TM TM
192 lib_name            : OK OK OK OK OK OK OK OK TM OK
193 read_pmu_cycle      : TM TM TM TM TM TM TM TM TM TM
194 read_pmu_cache      : TM TM TM TM TM TM TM TM TM TM
195 read_pmu_branch     : TM TM TM TM TM TM TM TM TM TM
197 filter_glob         : TM TM TM TM TM TM TM TM TM TM
198 lib_arg_float       : TM TM TM TM TM SK SK SK SK SK

It gets stuck after finishing 198 lib_arg_float.

[honggyukim]

The tests related to arguments are not actually the failures of ARM here.

$ ./runtest.py 062 -vdp -O0
Start 1 tests with 1 worker
Test case                 pg
------------------------: O0
build command: gcc -o t-exp-char -fno-inline -fno-builtin -fno-ipa-cp -fno-omit-frame-pointer -D_FORTIFY_SOURCE=0  -pg -O0  s-exp-char.c
test command: /home/honggyu/uftrace/uftrace --no-pager --no-event -L/home/honggyu/uftrace -A "foo@arg1/c,arg2/c,arg3/c" -A "bar@arg1/c,arg2/c,arg3/i,arg4/x8"
t-exp-char
=========== original ===========
# DURATION     TID     FUNCTION
   3.750 us [ 15223] | __monstartup();
   2.500 us [ 15223] | __cxa_atexit();
            [ 15223] | main() {
   5.521 us [ 15223] |   foo('f', 'o', 'o');
   1.250 us [ 15223] |   bar('\0', 'B', 97, 0x72);
  10.677 us [ 15223] | } /* main */

===========  result  ===========
main() {
   foo('f', 'o', 'o');
   bar('\0', 'B', 97, 0x72);
 } /* main */
=========== expected ===========
main() {
   foo('f', 'o', 'o');
   bar('\x00', 'B', 97, 0x72);
 } /* main */
t062_arg_char: diff result of -pg -O0
--- expect      2019-11-10 14:41:23.015886224 +0900
+++ result      2019-11-10 14:41:23.015886224 +0900
@@ -2,3 +2,3 @@
    foo('f', 'o', 'o');
-   bar('\x00', 'B', 97, 0x72);
+   bar('\0', 'B', 97, 0x72);
  } /* main */

062 arg_char            : NG

It can be fixed with the following change.

diff --git a/tests/t062_arg_char.py b/tests/t062_arg_char.py
index 2bcb9d3b..7a0305aa 100644
--- a/tests/t062_arg_char.py
+++ b/tests/t062_arg_char.py
@@ -8,7 +8,7 @@ class TestCase(TestBase):
 # DURATION    TID     FUNCTION
             [18279] | main() {
    0.371 ms [18279] |   foo('f', 'o', 'o');
-   0.923 ms [18279] |   bar('\\x00', 'B', 97, 0x72);
+   0.923 ms [18279] |   bar('\\0', 'B', 97, 0x72);
    3.281 ms [18279] | } /* main */
 """)

[honggyukim]

The tests 048 and from 119 to 121, they get crashed as follows:

048 malloc_impl         : TM TM TM TM TM TM TM TM TM TM
119 malloc_hook         : TM TM TM TM TM TM TM TM TM TM
120 malloc_tsd          : TM TM TM TM TM TM TM TM TM TM
121 malloc_fork         : TM TM TM TM TM TM TM TM TM TM

The reason of the crash is because raspberry pi doesn't have such amount of memory, so they can be fixed by reducing the memory size for those tests as follows:

diff --git a/tests/s-malloc-fork.c b/tests/s-malloc-fork.c
index 29a278a6..4c0f56ed 100644
--- a/tests/s-malloc-fork.c
+++ b/tests/s-malloc-fork.c
@@ -10,7 +10,7 @@ void (*real_free)(void *ptr);

 #define ALIGN(n, a)  (((n) + (a) - 1) & ~((a) - 1))

-#define MALLOC_BUFSIZE  (1024 * 1024 * 1024)
+#define MALLOC_BUFSIZE  (512 * 1024 * 1024)
 /* this is needed for optimized binaries */
 static char buf[MALLOC_BUFSIZE];

diff --git a/tests/s-malloc-hook.c b/tests/s-malloc-hook.c
index c221f98a..157c9ea4 100644
--- a/tests/s-malloc-hook.c
+++ b/tests/s-malloc-hook.c
@@ -8,7 +8,7 @@ void (*real_free)(void *ptr);

 #define ALIGN(n, a)  (((n) + (a) - 1) & ~((a) - 1))

-#define MALLOC_BUFSIZE  (1024 * 1024 * 1024)
+#define MALLOC_BUFSIZE  (512 * 1024 * 1024)
 /* this is needed for optimized binaries */
 static char buf[MALLOC_BUFSIZE];

diff --git a/tests/s-malloc-tsd.c b/tests/s-malloc-tsd.c
index aa70a9f8..abb29a56 100644
--- a/tests/s-malloc-tsd.c
+++ b/tests/s-malloc-tsd.c
@@ -12,7 +12,7 @@ void (*real_free)(void *ptr);

 #define ALIGN(n, a)  (((n) + (a) - 1) & ~((a) - 1))

-#define MALLOC_BUFSIZE  (1024 * 1024 * 1024)
+#define MALLOC_BUFSIZE  (512 * 1024 * 1024)
 /* this is needed for optimized binaries */
 static char buf[MALLOC_BUFSIZE];

diff --git a/tests/s-malloc.c b/tests/s-malloc.c
index 4fd80c8d..ea80358e 100644
--- a/tests/s-malloc.c
+++ b/tests/s-malloc.c
@@ -2,7 +2,7 @@

 #define ALIGN(n, a)  (((n) + (a) - 1) & ~((a) - 1))

-#define MALLOC_BUFSIZE  (1024 * 1024 * 1024)
+#define MALLOC_BUFSIZE  (512 * 1024 * 1024)

 int malloc_count;
 int free_count;

After applying the changes above, they are all passed.

$ ./runtest.py malloc_
Start 4 tests with 4 worker
Test case                 pg             finstrument-fu
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os
048 malloc_impl         : OK OK OK OK OK OK OK OK OK OK
119 malloc_hook         : OK OK OK OK OK OK OK OK OK OK
120 malloc_tsd          : OK OK OK OK OK OK OK OK OK OK
121 malloc_fork         : OK OK OK OK OK OK OK OK OK OK

[honggyukim]

Another problem is

152 read_proc_statm     : TM TM TM TM TM TM TM TM TM TM

Here is to simply reproduce the problem.

$ gcc -pg -o t-abc s-abc.c

$ uftrace record -T b@read=proc/statm t-abc

$ uftrace replay --no-pager
# DURATION     TID     FUNCTION
   6.146 us [ 18955] | __monstartup();
   4.687 us [ 18955] | __cxa_atexit();
            [ 18955] | main() {
            [ 18955] |   a() {
            [ 18955] |     b() {
            [ 18955] |       /* read:proc/statm (size=9644KB, rss=3324KB, shared=2564KB) */
            [ 18955] |       c() {
   6.042 us [ 18955] |         getpid();
  14.844 us [ 18955] |       } /* c */
        (... got stuck ...)

It seems that it has some problem on replay with read trigger.

[honggyukim]

The gdb log is

$ gdb -q --args ../uftrace replay --no-pager
    ...
(gdb) r
Starting program: /home/honggyu/uftrace/uftrace replay --no-pager
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
# DURATION     TID     FUNCTION
   6.146 us [ 18955] | __monstartup();
   4.687 us [ 18955] | __cxa_atexit();
            [ 18955] | main() {
            [ 18955] |   a() {
            [ 18955] |     b() {
            [ 18955] |       /* read:proc/statm (size=9644KB, rss=3324KB, shared=2564KB) */
            [ 18955] |       c() {
   6.042 us [ 18955] |         getpid();
  14.844 us [ 18955] |       } /* c */
^C
Program received signal SIGINT, Interrupt.
get_task_ustack (handle=0x7effefa0, idx=0) at /home/honggyu/uftrace/utils/fstack.c:1522
1522                            while (last->rstack.type != UFTRACE_ENTRY)
(gdb) bt
#0  get_task_ustack (handle=0x7effefa0, idx=0) at /home/honggyu/uftrace/utils/fstack.c:1522
#1  0x000495a2 in read_user_stack (handle=0x7effefa0, task=0x7effef24) at /home/honggyu/uftrace/utils/fstack.c:1593
#2  0x0004a362 in __read_rstack (handle=0x7effefa0, taskp=0x7effef9c, consume=true) at /home/honggyu/uftrace/utils/fstack.c:2062
#3  0x0004a776 in read_rstack (handle=0x7effefa0, task=0x7effef9c) at /home/honggyu/uftrace/utils/fstack.c:2210
#4  0x0002934c in command_replay (argc=0, argv=0x7efff3b0, opts=0x7efff148) at /home/honggyu/uftrace/cmds/replay.c:1154
#5  0x00015b4a in main (argc=0, argv=0x7efff3b0) at /home/honggyu/uftrace/uftrace.c:1184

It seems that it never reaches to UFTRACE_ENTRY. It just hits UFTRACE_EXIT and UFTRACE_EVENT repeatedly.

[namhyung]

Please send PRs once those patches work well for x86.

[honggyukim]

I added partial fixes in #1028. Confirmed that it also works fine in x86_64.

[honggyukim]

Many of the remaining failures include floating point argument handling issues.

[honggyukim]

The demangle related problem looks like symbol address matching problem.

./runtest.py 012 -vdp -O0
    ...
===========  result  ===========
main() {
   operator new();
   ABC::ABC();
   ABC::foo() {
     ABC::bar() {
       ABC::baz();
     } /* ABC::bar */
   } /* ABC::foo */
 } /* main */
 <1061c>();
=========== expected ===========
main() {
   operator new();
   ABC::ABC();
   ABC::foo() {
     ABC::bar() {
       ABC::baz();
     } /* ABC::bar */
   } /* ABC::foo */
 } /* main */
 std::ios_base::Init::~Init();
t012_demangle: diff result of -pg -O0
--- expect      2019-11-14 10:49:25.152065578 +0900
+++ result      2019-11-14 10:49:25.152065578 +0900
@@ -9 +9,2 @@
  } /* main */
+ <1061c>();

012 demangle            : NG

[honggyukim]

By investigating the problem of demangle as follows.

$ g++ -pg -o t-demangle tests/s-demangle.cpp
$ uftrace record t-demangle
$ uftrace replay
# DURATION     TID     FUNCTION
            [  2513] | _GLOBAL__sub_I_ABC::foo() {
            [  2513] |   __static_initialization_and_destruction_0() {
 483.957 us [  2513] |     std::ios_base::Init::Init();
   4.167 us [  2513] |     __aeabi_atexit();
 501.613 us [  2513] |   } /* __static_initialization_and_destruction_0 */
 503.749 us [  2513] | } /* _GLOBAL__sub_I_ABC::foo */
            [  2513] | main() {
   2.292 us [  2513] |   operator new();
   0.417 us [  2513] |   ABC::ABC();
            [  2513] |   ABC::foo() {
            [  2513] |     ABC::bar() {
   0.312 us [  2513] |       ABC::baz();
   1.615 us [  2513] |     } /* ABC::bar */
   2.604 us [  2513] |   } /* ABC::foo */
   8.490 us [  2513] | } /* main */
  36.198 us [  2513] | <1061c>();

The address of the last std::ios_base::Init::~Init looks weird.

$ cat uftrace.data/t-demangle.sym | c++filt
    ...
0000000000000604 P std::ios_base::Init::Init()
    ...
000000010000061c P std::ios_base::Init::~Init()
0000000100000628 ? __dynsym_end

I've seen some cases that cannot find the proper symbol in ARM/AArch64. It might be the same problem. I think it shouldn't have __dynsym_end at the end.

[honggyukim]

I found that it goes to wrong if statement in the following check. https://github.com/namhyung/uftrace/blob/7ddad19a271c92d020f1119aa89b3bed2665bf98/utils/symbol.c#L430-L433

The last std::ios_base::Init::~Init symbol is not expected to have sym.st_value, but it's not zero in this case. So the sym->addr calculation goes wrong.

Let's see the function load_dyn_symbol itself. It reads ELF info from installed libelf.so in the current setting. https://github.com/namhyung/uftrace/blob/7ddad19a271c92d020f1119aa89b3bed2665bf98/utils/symbol.c#L413-L433

It's from https://github.com/namhyung/uftrace/blob/7ddad19a271c92d020f1119aa89b3bed2665bf98/utils/symbol-libelf.h#L20

However, /usr/include/gelf.h in the system contains 64-bit version header.

$ cat /usr/include/gelf.h
    ...
/* Symbol table entry.  */
typedef Elf64_Sym GElf_Sym;

So it uses

$ cat /usr/include/elf.h
    ...
typedef struct
{
  Elf64_Word    st_name;                /* Symbol name (string tbl index) */
  unsigned char st_info;                /* Symbol type and binding */
  unsigned char st_other;               /* Symbol visibility */
  Elf64_Section st_shndx;               /* Section index */
  Elf64_Addr    st_value;               /* Symbol value */
  Elf64_Xword   st_size;                /* Symbol size */
} Elf64_Sym;

[honggyukim]

After changing to configure --without-libelf, the symbol is shown correctly. I'm not sure how to avoid installing 64-bit gelf.h in raspbian system.

[namhyung]

The GElf is designed to cover to handle both 32 bit and 64 bit systems so it chose the 64 bit one intentionally.

[honggyukim]

I tested ARM 32-bit again on the current master 4e06f06.

$ uftrace --version
uftrace v0.9.3-202-g4e06 ( dwarf python luajit tui perf sched dynamic )

Here are the failed tests.

012 demangle            : NG NG NG NG NG NG NG NG NG NG
043 full_demangle       : NG NG NG NG NG NG NG NG NG NG
052 nested_func         : OK OK OK OK OK NG NG NG NG NG
065 arg_order           : NG NG NG NG NG SK SK SK SK SK
082 arg_many            : NG NG NG NG NG SK SK SK SK SK
083 arg_float           : NG NG NG NG NG SK SK SK SK SK
084 arg_mixed           : NG NG NG NG NG SK SK SK SK SK
085 arg_reg             : NG NG NG NG NG SK SK SK SK SK
086 arg_stack           : NG NG NG NG NG SK SK SK SK SK
087 arg_variadic        : NG NG NG NG NG SK SK SK SK SK
117 time_range          : NG NG NG NG NG NG NG NG NG NG
124 exception           : NG NG NG NG NG NG NG NG NG NG
125 report_range        : NG NG NG NG NG NG NG NG NG NG
131 lib_dlopen          : NZ NZ NZ NZ NZ OK OK OK OK OK
136 dynamic             : BI BI BI BI BI BI BI BI BI BI
140 dynamic_xray        : BI BI BI BI BI BI BI BI BI BI
147 event_sdt           : BI BI BI BI BI BI BI BI BI BI
150 recv_event          : BI BI BI BI BI BI BI BI BI BI
151 recv_runcmd         : NG NG NG NG NG NG NG NG NG NG
152 read_proc_statm     : TM TM TM TM TM TM TM TM TM TM
153 read_page_fault     : TM TM TM TM TM TM TM TM TM TM
159 report_diff_policy2 : NG NG NG NG NG NG NG NG NG NG
164 report_sched        : OK OK OK OK OK OK OK NG OK OK
175 filter_time_read    : TM TM TM TM TM TM TM TM TM TM
179 arg_auto2           : OK OK TM TM OK OK TM TM OK TM
180 arg_auto3           : OK TM OK OK OK TM OK OK OK TM
184 arg_enum            : NG TM TM NG NG NG TM TM TM NG
185 exception2          : NG NG NG NG NG NG NG NG NG NG
186 exception3          : SG SG SG SG SG NG NG NG NG NG
193 read_pmu_cycle      : TM TM TM TM TM TM TM TM TM TM
194 read_pmu_cache      : TM TM TM TM TM TM TM TM TM TM
195 read_pmu_branch     : TM TM TM TM TM TM TM TM TM TM
198 lib_arg_float       : NG NG NG NG NG SK SK SK SK SK
200 lib_dlopen2         : TM TM TM TM TM TM TM TM TM TM
201 arg_dwarf1          : NG NG NG NG NG SK SK SK SK SK
202 arg_dwarf2          : TM TM TM TM TM SK SK SK SK SK
203 arg_dwarf3          : TM TM TM TM TM SK SK SK SK SK
204 arg_dwarf4          : TM TM TM TM TM SK SK SK SK SK
208 watch_cpu           : NG NG NG NG NG NG NG NG NG NG
216 no_libcall_report   : OK NG NG NG NG OK OK OK OK OK
222 external_data       : NG NG NG NG NG NG NG NG NG NG
224 dynamic_lib         : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
225 dynamic_size        : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
226 default_opts        : NG NG NG NG NG NG NG NG NG NG
227 read_pmu_cycle2     : TM TM TM TM TM TM TM TM TM TM
228 read_pmu_cycle3     : OK OK NG NG NG OK OK OK OK OK
232 dynamic_unpatch     : BI BI BI BI BI BI BI BI BI BI

[namhyung]

What about this?

diff --git a/utils/symbol-libelf.h b/utils/symbol-libelf.h
index b3005e0..ea9024c 100644
--- a/utils/symbol-libelf.h
+++ b/utils/symbol-libelf.h
@@ -36,8 +36,12 @@ struct uftrace_elf_iter {
 #define elf_get_name(elf, iter, name)                          \
                elf_strptr((elf)->handle, (iter)->str_idx, name)

+/* due to a bug in libelf on ARM, the sym should be zero-out */
 #define elf_get_symbol(elf, iter, idx)                         \
-               gelf_getsym((iter)->data, idx, &(iter)->sym)
+       do {                                                    \
+               memset(&(iter)->sym, 0, sizeof((iter)->sym));   \
+               gelf_getsym((iter)->data, idx, &(iter)->sym);   \
+       } while (0)

 #define elf_get_strtab(elf, iter, idx)                         \
                (iter)->str_idx = idx

[honggyukim]

Thanks, but what's this fix about?

[honggyukim]

Here is detail failure info for test 198.

$ ./runtest.py 198 -vdp -O0
    ...
t198_lib_arg_float: diff result of -pg -O0
--- expect      2019-12-30 13:17:24.303043775 +0900
+++ result      2019-12-30 13:17:24.303043775 +0900
@@ -1,4 +1,4 @@
 main() {
-   expf(1.000000) = 2.718282;
-   log(2.718282) = 1.000000;
+   expf(0.000000) = 0.000000;
+   log(0.000000) = 0.000000;
  } /* main */

198 lib_arg_float       : NG

[honggyukim]

Here is detail failure info for test 065

$ ./runtest.py 065 -vdp -O0
    ...
t065_arg_order: diff result of -pg -O0
--- expect      2019-12-30 13:21:17.242432915 +0900
+++ result      2019-12-30 13:21:17.242432915 +0900
@@ -3,3 +3,3 @@
    int_sub(1, 2);
-   int_mul(0x4, 3);
+   int_mul(3, 0x4);
    int_div(4, -2);

065 arg_order           : NG

It's strange that the test result is actually correct, but seems the order is changed in x86_64.

$ cat s-exp-int.c
    ...
int int_mul(long long a, int b)
{
        return a * b;
}
        ...
int main(int argc, char *argv[])
{
        int a, b, c, d;

        a = int_add(-1, 2);
        b = int_sub(1, 2);
        c = int_mul(3, 4);
        d = int_div(4, -2);

        return (a + b + c + d) ? 0 : 1;
}

[honggyukim]

It may have some problems on argument handling.

$ cat s-arg.c
        ...
int many(unsigned argc, ...)
{
        unsigned i;
        va_list ap;

        va_start(ap, argc);
        for (i = 0; i < argc; i++) {
                if (ints[i] != va_arg(ap, int))
                        return -1;
        }
        va_end(ap);

        return 0;
}
        ...
int main(int argc, char *argv[])
{
        unsigned n = 3;

        if (argc > 1)
                n = atoi(argv[1]);

        if (foo(n) < 0)
                return 1;
        if (many(nr_ints, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144) < 0)
                return 1;
        if (pass(n) < 0)
                return 1;
        return 0;
}

This is the test result in details for 082 test.

$ ./runtest.py 082 -vdp -O0
    ...
t082_arg_many: diff result of -pg -O0
--- expect      2019-12-30 13:27:33.941337217 +0900
+++ result      2019-12-30 13:27:33.941337217 +0900
@@ -12,3 +12,3 @@
    } /* foo */
-   many(12, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144);
+   many(12, 1, 1, 2, 0, 0, 0, 2126753828, 12, 1, 1, 2, 3);
    pass() {

082 arg_many            : NG

[honggyukim]

t085_arg_reg.py has to be skipped if the arch is not x86_64 because it uses x86_64 registers so always be failed.

t136_dynamic.py and t140_dynamic_xray.py are better to be skipped as well after checking if its arch is x86_64 or not.

I'm not sure about t086_arg_stack.py yet.

[honggyukim]

test 117 is failed as follows:

$ ./runtest.py 117 -vdp -O0
    ...
t117_time_range: diff result of -pg -O0
--- expect      2019-12-30 13:35:35.179886903 +0900
+++ result      2019-12-30 13:35:35.179886903 +0900
@@ -1 +1,6 @@
+ __monstartup();
+ __cxa_atexit();
+ main() {
+   a() {
+     b() {
        c() {

117 time_range          : NG

It doesn't simply work as follows:

$ uftrace replay -f time -r 4470391.693075853~
#     TIMESTAMP       FUNCTION
  4470391.692842885 | __monstartup();
  4470391.692853666 | __cxa_atexit();
  4470391.693072103 | main() {
  4470391.693073353 |   a() {
  4470391.693073926 |     b() {
  4470391.693075853 |       c() {
  4470391.693076946 |         getpid();
  4470391.693082780 |       } /* c */
  4470391.693083509 |     } /* b */
  4470391.693083926 |   } /* a */
  4470391.693084394 | } /* main */

[namhyung]

Thanks, but what's this fix about?

It's for test 012 demangle (link) and it tries to fix GElf symbol having a non-zero st_value.

[honggyukim]

Oh.. I see. I will test it again. Thanks!

[namhyung]

Hmm.. I tested in with my board, but it didn't fix the problem. Actually it requires more serious look at the way how it build symbol tables. Let's fix it later..

[namhyung]

The below patch fixed the problem in 117

diff --git a/utils/utils.c b/utils/utils.c
index 3ae97373..30254fbe 100644
--- a/utils/utils.c
+++ b/utils/utils.c
@@ -484,16 +484,15 @@ uint64_t parse_time(char *arg, int limited_digits)
 uint64_t parse_timestamp(char *arg)
 {
        char *sep;
-       unsigned long tmp;
-       uint64_t ts;
+       uint64_t ts, tmp;
        int len;

-       tmp = strtoul(arg, &sep, 0);
+       tmp = strtoull(arg, &sep, 0);
        ts = tmp * NSEC_PER_SEC;

        if (*sep == '.') {
                arg = sep + 1;
-               tmp = strtoul(arg, &sep, 0);
+               tmp = strtoull(arg, &sep, 0);

                len = 0;
                while (isdigit(*arg)) {

[namhyung]

And below fixed many problems regarding read triggers

diff --git a/utils/fstack.c b/utils/fstack.c
index 05310573..b9f15509 100644
--- a/utils/fstack.c
+++ b/utils/fstack.c
@@ -1512,15 +1512,16 @@ get_task_ustack(struct uftrace_data *handle, int idx)
                                }
                        }

-                       if (rstack_list->count == 0) {
+                       list_for_each_entry_reverse(last, &rstack_list->read, list) {
+                               if (last->rstack.type == UFTRACE_ENTRY)
+                                       break;
+                       }
+                       if (list_no_entry(last, &rstack_list->read, list)) {
                                /* it's already exceeded time filter, just return */
                                add_to_rstack_list(rstack_list, curr, &task->args);
                                break;
                        }

-                       last = list_last_entry(&rstack_list->read,
-                                              typeof(*last), list);
-
                        /* time filter is meaningful for functions */
                        while (last->rstack.type != UFTRACE_ENTRY)
                                last = list_prev_entry(last, list);

[honggyukim]

I was able to test the same problem in i386 mode with the following change.

diff --git a/tests/runtest.py b/tests/runtest.py
index 2056395..a38e252 100755
--- a/tests/runtest.py
+++ b/tests/runtest.py
@@ -537,6 +537,7 @@ def run_single_case(case, flags, opts, arg):
     for flag in flags:
         for opt in opts:
             cflags = ' '.join(["-" + flag, "-" + opt])
+            cflags += ' -m32'
             dif = ''
             ret = tc.build(tc.name, cflags)
             if ret == TestBase.TEST_SUCCESS:

I tested the above two fixes and found that they all work fine.

$ ./runtest.py 117
Start 1 tests with 1 worker
Test case                 pg             finstrument-fu
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os
117 time_range          : OK OK OK OK OK OK OK OK OK OK

$ ./runtest.py 152
Start 1 tests with 1 worker
Test case                 pg             finstrument-fu
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os
152 read_proc_statm     : OK OK OK OK OK OK OK OK OK OK

Thanks very much for the fixes.

[honggyukim]

It'd be better to have a way to provide such -m32 flag to runtest.py. I would like also to have a way to compile test programs with -mthumb -march=armv7 as well for thumb mode testing.

[honggyukim]

The read trigger related change seems to fix the following failures.

152 read_proc_statm     : TM TM TM TM TM TM TM TM TM TM
153 read_page_fault     : TM TM TM TM TM TM TM TM TM TM
175 filter_time_read    : TM TM TM TM TM TM TM TM TM TM
193 read_pmu_cycle      : TM TM TM TM TM TM TM TM TM TM
194 read_pmu_cache      : TM TM TM TM TM TM TM TM TM TM
195 read_pmu_branch     : TM TM TM TM TM TM TM TM TM TM
222 external_data       : NG NG NG NG NG NG NG NG NG NG
227 read_pmu_cycle2     : TM TM TM TM TM TM TM TM TM TM

They are all passed after applying your fix. Thanks!

[namhyung]

You can pass a single option with -f option like -f m32, but it wouldn't support passing multiple options for now.

[namhyung]

Merged: 367945f4

[honggyukim]

Thanks for the fixes. If possible, could you please run tests compiling them in thumb mode? I will also try it as well.

[namhyung]

Unfortunately I was unable to compile it with thumb mode.

[honggyukim]

How about compiling with this?

diff --git a/tests/runtest.py b/tests/runtest.py
index 2056395..a38e252 100755
--- a/tests/runtest.py
+++ b/tests/runtest.py
@@ -537,6 +537,7 @@ def run_single_case(case, flags, opts, arg):
     for flag in flags:
         for opt in opts:
             cflags = ' '.join(["-" + flag, "-" + opt])
+            cflags += ' -mthumb -march=armv7'
             dif = ''
             ret = tc.build(tc.name, cflags)
             if ret == TestBase.TEST_SUCCESS:

[honggyukim]

You can pass a single option with -f option like -f m32, but it wouldn't support passing multiple options for now.

Hmm.. It actually doesn't work.

$ ./runtest.py -f m32 001
Start 1 tests with 1 worker
Test case                 m32
------------------------: O0 O1 O2 O3 Os
001 basic               : NZ NZ NZ NZ NZ

[namhyung]

It seems rest of the remaining failures are not easy to fix. Will take a look at them later..