yangyongyong
2018-02-13 04:15:42 UTC
Hi all,
Recently I upgrade libunwind from 1.2 to 1.3 (until commit 26718da1713a5698070e702e68db1f995baeae07) mostly because commit 5a491cb2d889f03952182d611d2ac6e15c3c5845:
"arm64: Support for restore of ARM64 Neon callee-saved registers during unwind"
v1.3 works well except the performance regression of unw_get_proc_info.
I sampled the time consumed by unw_get_proc_info with clock_gettime(CLOCK_MONOTONIC, ...)
Here is the results (Tests are performed on aarch64/linux with gcc 5.4, us means microsecond):
v1.3:
-- unw_get_proc_info called 6603, time(us) consumed total 620254, time(us) consumed delta 68
-- unw_get_proc_info called 6604, time(us) consumed total 620322, time(us) consumed delta 49
-- unw_get_proc_info called 6605, time(us) consumed total 620371, time(us) consumed delta 60
-- unw_get_proc_info called 6606, time(us) consumed total 620431, time(us) consumed delta 80
-- unw_get_proc_info called 6607, time(us) consumed total 620511, time(us) consumed delta 77
-- unw_get_proc_info called 6608, time(us) consumed total 620588, time(us) consumed delta 88
-- unw_get_proc_info called 6609, time(us) consumed total 620676, time(us) consumed delta 201
-- unw_get_proc_info called 6610, time(us) consumed total 620877, time(us) consumed delta 200
-- unw_get_proc_info called 6611, time(us) consumed total 621077, time(us) consumed delta 185
-- unw_get_proc_info called 6612, time(us) consumed total 621262, time(us) consumed delta 151
-- unw_get_proc_info called 6613, time(us) consumed total 621413, time(us) consumed delta 136
-- unw_get_proc_info called 6614, time(us) consumed total 621549, time(us) consumed delta 75
-- unw_get_proc_info called 6615, time(us) consumed total 621624, time(us) consumed delta 66
-- unw_get_proc_info called 6616, time(us) consumed total 621690, time(us) consumed delta 57
-- unw_get_proc_info called 6617, time(us) consumed total 621747, time(us) consumed delta 78
-- unw_get_proc_info called 6618, time(us) consumed total 621825, time(us) consumed delta 80
-- unw_get_proc_info called 6619, time(us) consumed total 621905, time(us) consumed delta 79
-- unw_get_proc_info called 6620, time(us) consumed total 621984, time(us) consumed delta 78
-- unw_get_proc_info called 6621, time(us) consumed total 622062, time(us) consumed delta 78
-- unw_get_proc_info called 6622, time(us) consumed total 622140, time(us) consumed delta 79
-- unw_get_proc_info called 6623, time(us) consumed total 622219, time(us) consumed delta 78
-- unw_get_proc_info called 6624, time(us) consumed total 622297, time(us) consumed delta 66
-- unw_get_proc_info called 6625, time(us) consumed total 622363, time(us) consumed delta 49
-- unw_get_proc_info called 6626, time(us) consumed total 622412, time(us) consumed delta 61
-- unw_get_proc_info called 6627, time(us) consumed total 622473, time(us) consumed delta 81
v1.2
-- unw_get_proc_info called 6289, time(us) consumed total 45070, time(us) consumed delta 10
-- unw_get_proc_info called 6290, time(us) consumed total 45080, time(us) consumed delta 4
-- unw_get_proc_info called 6291, time(us) consumed total 45084, time(us) consumed delta 3
-- unw_get_proc_info called 6292, time(us) consumed total 45087, time(us) consumed delta 5
-- unw_get_proc_info called 6293, time(us) consumed total 45092, time(us) consumed delta 3
-- unw_get_proc_info called 6294, time(us) consumed total 45095, time(us) consumed delta 7
-- unw_get_proc_info called 6295, time(us) consumed total 45102, time(us) consumed delta 4
-- unw_get_proc_info called 6296, time(us) consumed total 45106, time(us) consumed delta 6
-- unw_get_proc_info called 6297, time(us) consumed total 45112, time(us) consumed delta 8
-- unw_get_proc_info called 6298, time(us) consumed total 45120, time(us) consumed delta 7
-- unw_get_proc_info called 6299, time(us) consumed total 45127, time(us) consumed delta 8
-- unw_get_proc_info called 6300, time(us) consumed total 45135, time(us) consumed delta 8
-- unw_get_proc_info called 6301, time(us) consumed total 45143, time(us) consumed delta 8
-- unw_get_proc_info called 6302, time(us) consumed total 45151, time(us) consumed delta 9
-- unw_get_proc_info called 6303, time(us) consumed total 45160, time(us) consumed delta 8
-- unw_get_proc_info called 6304, time(us) consumed total 45168, time(us) consumed delta 9
-- unw_get_proc_info called 6305, time(us) consumed total 45177, time(us) consumed delta 7
-- unw_get_proc_info called 6306, time(us) consumed total 45184, time(us) consumed delta 6
-- unw_get_proc_info called 6307, time(us) consumed total 45190, time(us) consumed delta 7
-- unw_get_proc_info called 6308, time(us) consumed total 45197, time(us) consumed delta 7
-- unw_get_proc_info called 6309, time(us) consumed total 45204, time(us) consumed delta 7
-- unw_get_proc_info called 6310, time(us) consumed total 45211, time(us) consumed delta 4
-- unw_get_proc_info called 6311, time(us) consumed total 45215, time(us) consumed delta 3
-- unw_get_proc_info called 6312, time(us) consumed total 45218, time(us) consumed delta 5
-- unw_get_proc_info called 6313, time(us) consumed total 45223, time(us) consumed delta 3
-- unw_get_proc_info called 6314, time(us) consumed total 45226, time(us) consumed delta 8
-- unw_get_proc_info called 6315, time(us) consumed total 45234, time(us) consumed delta 5
-- unw_get_proc_info called 6316, time(us) consumed total 45239, time(us) consumed delta 6
-- unw_get_proc_info called 6317, time(us) consumed total 45245, time(us) consumed delta 8
-- unw_get_proc_info called 6318, time(us) consumed total 45253, time(us) consumed delta 8
-- unw_get_proc_info called 6319, time(us) consumed total 45261, time(us) consumed delta 8
-- unw_get_proc_info called 6320, time(us) consumed total 45269, time(us) consumed delta 9
-- unw_get_proc_info called 6321, time(us) consumed total 45278, time(us) consumed delta 10
-- unw_get_proc_info called 6322, time(us) consumed total 45288, time(us) consumed delta 8
-- unw_get_proc_info called 6323, time(us) consumed total 45296, time(us) consumed delta 8
-- unw_get_proc_info called 6324, time(us) consumed total 45304, time(us) consumed delta 9
-- unw_get_proc_info called 6325, time(us) consumed total 45313, time(us) consumed delta 6
-- unw_get_proc_info called 6326, time(us) consumed total 45319, time(us) consumed delta 6
It seems v1.3 costs 10 times more. And things are getting even worse on qemu. I do not have any clue for this problem, please some one enlights me.
By the way, v1.3 can not be built on Android NDK r16b (https://dl.google.com/android/repository/android-ndk-r16b-linux-x86_64.zip ) with configure : "configure --host=aarch64-linux-android --prefix=xxx_install_yyy --enable-debug". Following are some potential problems:
1. test-coredump-unwind includes execinfo.h which does not exist on android.
2. HAVE_STRUCT_ELF_PRSTATUS is not defined during configuration.
3. struct elf_prstatus is defined in linux/elfcore.h which is not included.
Best regards.
Recently I upgrade libunwind from 1.2 to 1.3 (until commit 26718da1713a5698070e702e68db1f995baeae07) mostly because commit 5a491cb2d889f03952182d611d2ac6e15c3c5845:
"arm64: Support for restore of ARM64 Neon callee-saved registers during unwind"
v1.3 works well except the performance regression of unw_get_proc_info.
I sampled the time consumed by unw_get_proc_info with clock_gettime(CLOCK_MONOTONIC, ...)
Here is the results (Tests are performed on aarch64/linux with gcc 5.4, us means microsecond):
v1.3:
-- unw_get_proc_info called 6603, time(us) consumed total 620254, time(us) consumed delta 68
-- unw_get_proc_info called 6604, time(us) consumed total 620322, time(us) consumed delta 49
-- unw_get_proc_info called 6605, time(us) consumed total 620371, time(us) consumed delta 60
-- unw_get_proc_info called 6606, time(us) consumed total 620431, time(us) consumed delta 80
-- unw_get_proc_info called 6607, time(us) consumed total 620511, time(us) consumed delta 77
-- unw_get_proc_info called 6608, time(us) consumed total 620588, time(us) consumed delta 88
-- unw_get_proc_info called 6609, time(us) consumed total 620676, time(us) consumed delta 201
-- unw_get_proc_info called 6610, time(us) consumed total 620877, time(us) consumed delta 200
-- unw_get_proc_info called 6611, time(us) consumed total 621077, time(us) consumed delta 185
-- unw_get_proc_info called 6612, time(us) consumed total 621262, time(us) consumed delta 151
-- unw_get_proc_info called 6613, time(us) consumed total 621413, time(us) consumed delta 136
-- unw_get_proc_info called 6614, time(us) consumed total 621549, time(us) consumed delta 75
-- unw_get_proc_info called 6615, time(us) consumed total 621624, time(us) consumed delta 66
-- unw_get_proc_info called 6616, time(us) consumed total 621690, time(us) consumed delta 57
-- unw_get_proc_info called 6617, time(us) consumed total 621747, time(us) consumed delta 78
-- unw_get_proc_info called 6618, time(us) consumed total 621825, time(us) consumed delta 80
-- unw_get_proc_info called 6619, time(us) consumed total 621905, time(us) consumed delta 79
-- unw_get_proc_info called 6620, time(us) consumed total 621984, time(us) consumed delta 78
-- unw_get_proc_info called 6621, time(us) consumed total 622062, time(us) consumed delta 78
-- unw_get_proc_info called 6622, time(us) consumed total 622140, time(us) consumed delta 79
-- unw_get_proc_info called 6623, time(us) consumed total 622219, time(us) consumed delta 78
-- unw_get_proc_info called 6624, time(us) consumed total 622297, time(us) consumed delta 66
-- unw_get_proc_info called 6625, time(us) consumed total 622363, time(us) consumed delta 49
-- unw_get_proc_info called 6626, time(us) consumed total 622412, time(us) consumed delta 61
-- unw_get_proc_info called 6627, time(us) consumed total 622473, time(us) consumed delta 81
v1.2
-- unw_get_proc_info called 6289, time(us) consumed total 45070, time(us) consumed delta 10
-- unw_get_proc_info called 6290, time(us) consumed total 45080, time(us) consumed delta 4
-- unw_get_proc_info called 6291, time(us) consumed total 45084, time(us) consumed delta 3
-- unw_get_proc_info called 6292, time(us) consumed total 45087, time(us) consumed delta 5
-- unw_get_proc_info called 6293, time(us) consumed total 45092, time(us) consumed delta 3
-- unw_get_proc_info called 6294, time(us) consumed total 45095, time(us) consumed delta 7
-- unw_get_proc_info called 6295, time(us) consumed total 45102, time(us) consumed delta 4
-- unw_get_proc_info called 6296, time(us) consumed total 45106, time(us) consumed delta 6
-- unw_get_proc_info called 6297, time(us) consumed total 45112, time(us) consumed delta 8
-- unw_get_proc_info called 6298, time(us) consumed total 45120, time(us) consumed delta 7
-- unw_get_proc_info called 6299, time(us) consumed total 45127, time(us) consumed delta 8
-- unw_get_proc_info called 6300, time(us) consumed total 45135, time(us) consumed delta 8
-- unw_get_proc_info called 6301, time(us) consumed total 45143, time(us) consumed delta 8
-- unw_get_proc_info called 6302, time(us) consumed total 45151, time(us) consumed delta 9
-- unw_get_proc_info called 6303, time(us) consumed total 45160, time(us) consumed delta 8
-- unw_get_proc_info called 6304, time(us) consumed total 45168, time(us) consumed delta 9
-- unw_get_proc_info called 6305, time(us) consumed total 45177, time(us) consumed delta 7
-- unw_get_proc_info called 6306, time(us) consumed total 45184, time(us) consumed delta 6
-- unw_get_proc_info called 6307, time(us) consumed total 45190, time(us) consumed delta 7
-- unw_get_proc_info called 6308, time(us) consumed total 45197, time(us) consumed delta 7
-- unw_get_proc_info called 6309, time(us) consumed total 45204, time(us) consumed delta 7
-- unw_get_proc_info called 6310, time(us) consumed total 45211, time(us) consumed delta 4
-- unw_get_proc_info called 6311, time(us) consumed total 45215, time(us) consumed delta 3
-- unw_get_proc_info called 6312, time(us) consumed total 45218, time(us) consumed delta 5
-- unw_get_proc_info called 6313, time(us) consumed total 45223, time(us) consumed delta 3
-- unw_get_proc_info called 6314, time(us) consumed total 45226, time(us) consumed delta 8
-- unw_get_proc_info called 6315, time(us) consumed total 45234, time(us) consumed delta 5
-- unw_get_proc_info called 6316, time(us) consumed total 45239, time(us) consumed delta 6
-- unw_get_proc_info called 6317, time(us) consumed total 45245, time(us) consumed delta 8
-- unw_get_proc_info called 6318, time(us) consumed total 45253, time(us) consumed delta 8
-- unw_get_proc_info called 6319, time(us) consumed total 45261, time(us) consumed delta 8
-- unw_get_proc_info called 6320, time(us) consumed total 45269, time(us) consumed delta 9
-- unw_get_proc_info called 6321, time(us) consumed total 45278, time(us) consumed delta 10
-- unw_get_proc_info called 6322, time(us) consumed total 45288, time(us) consumed delta 8
-- unw_get_proc_info called 6323, time(us) consumed total 45296, time(us) consumed delta 8
-- unw_get_proc_info called 6324, time(us) consumed total 45304, time(us) consumed delta 9
-- unw_get_proc_info called 6325, time(us) consumed total 45313, time(us) consumed delta 6
-- unw_get_proc_info called 6326, time(us) consumed total 45319, time(us) consumed delta 6
It seems v1.3 costs 10 times more. And things are getting even worse on qemu. I do not have any clue for this problem, please some one enlights me.
By the way, v1.3 can not be built on Android NDK r16b (https://dl.google.com/android/repository/android-ndk-r16b-linux-x86_64.zip ) with configure : "configure --host=aarch64-linux-android --prefix=xxx_install_yyy --enable-debug". Following are some potential problems:
1. test-coredump-unwind includes execinfo.h which does not exist on android.
2. HAVE_STRUCT_ELF_PRSTATUS is not defined during configuration.
3. struct elf_prstatus is defined in linux/elfcore.h which is not included.
Best regards.