奇怪的分析结果与zlib

Weird profiling results with zlib

本文关键字：结果 zlib      更新时间：2023-10-16

我正在玩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秒。

我在带有clang的MacOS上也做了同样的尝试，在时间上没有太大的区别。

我尝试了不同级别的优化，结果仍然存在-如果您注释，您将获得约10倍的执行时间

原因是什么?

我尝试了Cygwin与gcc -没有区别的时间。

我在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

所以并不是你的代码突然变慢了6倍，它实际上在内核中花费了5000多倍的时间，这是不寻常的，因为程序只是根据其本质进行计算，没有I/O或类似的东西。

oprofile证明了这一点，好的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

这里有一个内存分配-释放循环。我们在这里使用动态内存分配/释放的唯一东西是输出字符串，实际上，如果您留下未注释的神奇字符串，但初始化字符串，如std::string out = "1";，您将获得与附加到字符串相同的"好"结果。

这一定是分配逻辑中的某个特殊情况，在这种情况下，您的usage-unusage模式触发glibc首先分配一些内存(通过brk()分配一个小块)，然后将其释放回系统。对于初始化(静态或追加)字符串，您有一个不同的使用模式，glibc不能将内存返回给系统。如果强制glibc不返回任何内存(参见man mallopt)，那么即使使用"bad"(注释)二进制，结果也是一样的:

$ time MALLOC_TRIM_THRESHOLD_=-1 ./main 
real    0m5.094s
user    0m5.096s
sys     0m0.000s
在现实生活中，你很可能不会遇到这种情况。此外，如果您使用的是不同的C库(甚至是不同版本的glibc)，那么结果也可能不同。
相关文章：