zlib 的奇怪分析结果
Weird profiling results with zlib
我正在玩 zlib
并且有这样的(简化)代码:
#include <cstring> // memset
#include <string>
#include <zlib.h>
#include <cstdio>
const int compressionLevel_ = 9;
const size_t BUFFER_SIZE = 1024 * 8;
char buffer_[BUFFER_SIZE];
std::string compress(const char *data, size_t const size){
z_stream zs;
memset(&zs, 0, sizeof(zs));
if (deflateInit(&zs, compressionLevel_) != Z_OK)
return {};
zs.next_in = reinterpret_cast<Bytef *>( const_cast<char *>( data ) );
zs.avail_in = static_cast<uInt>( size );
std::string out;
int result;
do {
zs.next_out = reinterpret_cast<Bytef *>(buffer_);
zs.avail_out = BUFFER_SIZE;
result = deflate(&zs, Z_FINISH);
if (out.size() < zs.total_out){
// COMMENT / UNCOMMENT HERE !!!
out.append(buffer_, zs.total_out - out.size() );
}
} while (result == Z_OK);
deflateEnd(&zs);
if (result != Z_STREAM_END)
return {};
return out;
}
int main(){
const char *original = "Hello World";
size_t const original_size = strlen(original);
for(size_t i = 0; i < 1000000; ++i){
const auto cdata = compress(original, original_size);
}
}
真正的代码有点大,因为它解压缩并检查解压缩的字符串与原始字符串。
如果我用 clang 或 gcc 编译,一切都执行大约 5 秒。
但是...如果我评论这一行:
if (out.size() < zs.total_out){
// COMMENT / UNCOMMENT HERE !!!
// out.append(buffer_, zs.total_out - out.size() );
}
执行需要 30 秒!!!
如果我尝试快速 Linux 服务器,时间分别是 3 秒和 18 秒。
我在 MacOS 上使用 clang 进行了同样的尝试,时间上没有太大差异。
我尝试了不同级别的优化,结果仍然存在 - 如果您发表评论,您将获得大约 10 倍的执行时间。
可能是什么原因?
更新
我用 gcc 在 Cygwin 上试过 - 时间上没有区别。
我厌倦了 Linux Arm CPU 与 gcc - 25 秒 vs 2:20 分钟。
如果你 运行 它与 time
,你会注意到一个有趣的事情,没有注释的行你会得到这样的东西:
$ time ./main
real 0m5.309s
user 0m5.304s
sys 0m0.004s
没什么特别的,只是在用户空间中花费了 5 秒钟,正如预期的那样。但是用行评论你突然得到这个:
$ time ./main
real 0m29.061s
user 0m7.424s
sys 0m21.660s
所以并不是你的代码突然变慢了六倍,它实际上在内核中花费了 5000 多倍,考虑到程序只是根据其本质计算事物,这是不寻常的,不 I/O或类似的东西。
oprofile 证明了这一点,好的证明了这一点:
samples % image name symbol name
62451 45.2376 libz.so.1.2.8 /lib64/libz.so.1.2.8
61905 44.8421 libc-2.19.so memset
2752 1.9935 libc-2.19.so _int_free
2549 1.8464 libc-2.19.so _int_malloc
2474 1.7921 libc-2.19.so malloc_consolidate
2263 1.6392 no-vmlinux /no-vmlinux
1365 0.9888 libc-2.19.so malloc
723 0.5237 libc-2.19.so __memcpy_sse2_unaligned
711 0.5150 libstdc++.so.6.0.21 /usr/lib64/libstdc++.so.6.0.21
478 0.3462 libc-2.19.so free
366 0.2651 main main
6 0.0043 ld-2.19.so _dl_lookup_symbol_x
2 0.0014 ld-2.19.so _dl_relocate_object
2 0.0014 ld-2.19.so do_lookup_x
1 7.2e-04 ld-2.19.so _dl_name_match_p
1 7.2e-04 ld-2.19.so check_match.9478
1 7.2e-04 ld-2.19.so strcmp
1 7.2e-04 libc-2.19.so _dl_addr
而坏的是这样的:
samples % image name symbol name
594605 74.6032 no-vmlinux /no-vmlinux
102981 12.9207 libc-2.19.so memset
72822 9.1368 libz.so.1.2.8 /lib64/libz.so.1.2.8
9093 1.1409 libc-2.19.so _int_malloc
3987 0.5002 libc-2.19.so sysmalloc
3365 0.4222 libc-2.19.so _int_free
2119 0.2659 libc-2.19.so brk
1958 0.2457 libc-2.19.so systrim.isra.1
1597 0.2004 libc-2.19.so free
1217 0.1527 libc-2.19.so malloc
1123 0.1409 libc-2.19.so sbrk
786 0.0986 libc-2.19.so __memcpy_sse2_unaligned
688 0.0863 libc-2.19.so __default_morecore
669 0.0839 main main
5 6.3e-04 ld-2.19.so _dl_relocate_object
4 5.0e-04 ld-2.19.so do_lookup_x
2 2.5e-04 ld-2.19.so strcmp
1 1.3e-04 ld-2.19.so _dl_lookup_symbol_x
1 1.3e-04 libc-2.19.so _dl_addr
如果您还查看了两个二进制文件的 strace
,好的二进制文件只进行了 64 次系统调用(至少在我的系统上是这样),而坏的二进制文件进行了 4000063 次系统调用,其中大部分看起来像这样:
brk(0x6c0000) = 0x6c0000
brk(0x6e2000) = 0x6e2000
brk(0x6d2000) = 0x6d2000
brk(0x6c2000) = 0x6c2000
brk(0x6c0000) = 0x6c0000
brk(0x6e2000) = 0x6e2000
brk(0x6d2000) = 0x6d2000
brk(0x6c2000) = 0x6c2000
brk(0x6c0000) = 0x6c0000
所以,我们这里有内存分配-释放循环。我们这里唯一使用动态内存 allocation/deallocation 的是输出字符串,事实上,如果你不注释魔术字符串,但像 std::string out = "1";
一样初始化字符串,你会得到相同的 "good" 结果与附加到字符串一样。
这一定是分配逻辑中的一些极端情况,您的使用-未使用模式触发 glibc 首先分配一些内存(一小块,因此通过 brk()
),然后将其释放回系统.使用初始化(静态或附加到)字符串,您有不同的使用模式,glibc 不能 return 内存到系统。如果您强制 glibc 不 return 任何内存(请参阅 man mallopt
),那么即使使用 "bad"(已注释)二进制文件,结果也是相同的:
$ time MALLOC_TRIM_THRESHOLD_=-1 ./main
real 0m5.094s
user 0m5.096s
sys 0m0.000s
您很可能不会在现实生活中遇到这种极端情况。此外,如果您使用的是一些不同的 C 库(甚至是不同版本的 glibc),那么结果也可能不同。
我正在玩 zlib
并且有这样的(简化)代码:
#include <cstring> // memset
#include <string>
#include <zlib.h>
#include <cstdio>
const int compressionLevel_ = 9;
const size_t BUFFER_SIZE = 1024 * 8;
char buffer_[BUFFER_SIZE];
std::string compress(const char *data, size_t const size){
z_stream zs;
memset(&zs, 0, sizeof(zs));
if (deflateInit(&zs, compressionLevel_) != Z_OK)
return {};
zs.next_in = reinterpret_cast<Bytef *>( const_cast<char *>( data ) );
zs.avail_in = static_cast<uInt>( size );
std::string out;
int result;
do {
zs.next_out = reinterpret_cast<Bytef *>(buffer_);
zs.avail_out = BUFFER_SIZE;
result = deflate(&zs, Z_FINISH);
if (out.size() < zs.total_out){
// COMMENT / UNCOMMENT HERE !!!
out.append(buffer_, zs.total_out - out.size() );
}
} while (result == Z_OK);
deflateEnd(&zs);
if (result != Z_STREAM_END)
return {};
return out;
}
int main(){
const char *original = "Hello World";
size_t const original_size = strlen(original);
for(size_t i = 0; i < 1000000; ++i){
const auto cdata = compress(original, original_size);
}
}
真正的代码有点大,因为它解压缩并检查解压缩的字符串与原始字符串。
如果我用 clang 或 gcc 编译,一切都执行大约 5 秒。
但是...如果我评论这一行:
if (out.size() < zs.total_out){
// COMMENT / UNCOMMENT HERE !!!
// out.append(buffer_, zs.total_out - out.size() );
}
执行需要 30 秒!!!
如果我尝试快速 Linux 服务器,时间分别是 3 秒和 18 秒。
我在 MacOS 上使用 clang 进行了同样的尝试,时间上没有太大差异。
我尝试了不同级别的优化,结果仍然存在 - 如果您发表评论,您将获得大约 10 倍的执行时间。
可能是什么原因?
更新
我用 gcc 在 Cygwin 上试过 - 时间上没有区别。
我厌倦了 Linux Arm CPU 与 gcc - 25 秒 vs 2:20 分钟。
如果你 运行 它与 time
,你会注意到一个有趣的事情,没有注释的行你会得到这样的东西:
$ time ./main
real 0m5.309s
user 0m5.304s
sys 0m0.004s
没什么特别的,只是在用户空间中花费了 5 秒钟,正如预期的那样。但是用行评论你突然得到这个:
$ time ./main
real 0m29.061s
user 0m7.424s
sys 0m21.660s
所以并不是你的代码突然变慢了六倍,它实际上在内核中花费了 5000 多倍,考虑到程序只是根据其本质计算事物,这是不寻常的,不 I/O或类似的东西。
oprofile 证明了这一点,好的证明了这一点:
samples % image name symbol name
62451 45.2376 libz.so.1.2.8 /lib64/libz.so.1.2.8
61905 44.8421 libc-2.19.so memset
2752 1.9935 libc-2.19.so _int_free
2549 1.8464 libc-2.19.so _int_malloc
2474 1.7921 libc-2.19.so malloc_consolidate
2263 1.6392 no-vmlinux /no-vmlinux
1365 0.9888 libc-2.19.so malloc
723 0.5237 libc-2.19.so __memcpy_sse2_unaligned
711 0.5150 libstdc++.so.6.0.21 /usr/lib64/libstdc++.so.6.0.21
478 0.3462 libc-2.19.so free
366 0.2651 main main
6 0.0043 ld-2.19.so _dl_lookup_symbol_x
2 0.0014 ld-2.19.so _dl_relocate_object
2 0.0014 ld-2.19.so do_lookup_x
1 7.2e-04 ld-2.19.so _dl_name_match_p
1 7.2e-04 ld-2.19.so check_match.9478
1 7.2e-04 ld-2.19.so strcmp
1 7.2e-04 libc-2.19.so _dl_addr
而坏的是这样的:
samples % image name symbol name
594605 74.6032 no-vmlinux /no-vmlinux
102981 12.9207 libc-2.19.so memset
72822 9.1368 libz.so.1.2.8 /lib64/libz.so.1.2.8
9093 1.1409 libc-2.19.so _int_malloc
3987 0.5002 libc-2.19.so sysmalloc
3365 0.4222 libc-2.19.so _int_free
2119 0.2659 libc-2.19.so brk
1958 0.2457 libc-2.19.so systrim.isra.1
1597 0.2004 libc-2.19.so free
1217 0.1527 libc-2.19.so malloc
1123 0.1409 libc-2.19.so sbrk
786 0.0986 libc-2.19.so __memcpy_sse2_unaligned
688 0.0863 libc-2.19.so __default_morecore
669 0.0839 main main
5 6.3e-04 ld-2.19.so _dl_relocate_object
4 5.0e-04 ld-2.19.so do_lookup_x
2 2.5e-04 ld-2.19.so strcmp
1 1.3e-04 ld-2.19.so _dl_lookup_symbol_x
1 1.3e-04 libc-2.19.so _dl_addr
如果您还查看了两个二进制文件的 strace
,好的二进制文件只进行了 64 次系统调用(至少在我的系统上是这样),而坏的二进制文件进行了 4000063 次系统调用,其中大部分看起来像这样:
brk(0x6c0000) = 0x6c0000
brk(0x6e2000) = 0x6e2000
brk(0x6d2000) = 0x6d2000
brk(0x6c2000) = 0x6c2000
brk(0x6c0000) = 0x6c0000
brk(0x6e2000) = 0x6e2000
brk(0x6d2000) = 0x6d2000
brk(0x6c2000) = 0x6c2000
brk(0x6c0000) = 0x6c0000
所以,我们这里有内存分配-释放循环。我们这里唯一使用动态内存 allocation/deallocation 的是输出字符串,事实上,如果你不注释魔术字符串,但像 std::string out = "1";
一样初始化字符串,你会得到相同的 "good" 结果与附加到字符串一样。
这一定是分配逻辑中的一些极端情况,您的使用-未使用模式触发 glibc 首先分配一些内存(一小块,因此通过 brk()
),然后将其释放回系统.使用初始化(静态或附加到)字符串,您有不同的使用模式,glibc 不能 return 内存到系统。如果您强制 glibc 不 return 任何内存(请参阅 man mallopt
),那么即使使用 "bad"(已注释)二进制文件,结果也是相同的:
$ time MALLOC_TRIM_THRESHOLD_=-1 ./main
real 0m5.094s
user 0m5.096s
sys 0m0.000s
您很可能不会在现实生活中遇到这种极端情况。此外,如果您使用的是一些不同的 C 库(甚至是不同版本的 glibc),那么结果也可能不同。