【问题标题】:Weird profiling results with zlibzlib 的奇怪分析结果
【发布时间】:2016-09-14 13:55:44
【问题描述】:

我正在玩 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 倍的执行时间。

可能是什么原因?

更新

我在 Cygwin 上用 gcc 试过 - 那里的时间没有区别。

我厌倦了使用 gcc 的 Linux Arm CPU - 25 秒 vs 2:20 分钟。

【问题讨论】:

    标签: c++ linux gcc clang zlib


    【解决方案1】:

    如果你用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
    

    所以,我们这里有内存分配-释放循环。我们在这里使用动态内存分配/释放的唯一内容是输出字符串,实际上,如果您不注释魔术字符串,但像 std::string out = "1"; 这样初始化字符串,您会得到与附加到字符串相同的“好”结果.

    这一定是分配逻辑中的一些极端情况,您的未使用模式触发 glibc 首先分配一些内存(一个小块,因此通过brk())然后将其释放回系统。使用初始化(静态或附加到)字符串时,您有不同的使用模式,并且 glibc 无法将内存返回给系统。如果您强制 glibc 不返回任何内存(请参阅 man mallopt),那么即使使用“坏”(已注释)二进制文件,结果也是一样的:

    $ time MALLOC_TRIM_THRESHOLD_=-1 ./main 
    
    real    0m5.094s
    user    0m5.096s
    sys     0m0.000s
    

    您很可能不会在现实生活中遇到这种极端情况。另外,如果你使用了一些不同的 C 库(甚至是不同版本的 glibc),那么结果也可能不同。

    【讨论】:

    • 我做了一些其他的测试——而不是只压缩 hello world,我将数字压缩为字符串。在这种情况下,没有这样的延误。但是代码不是很干净,我想在发布之前将其清理干净。 MacOS 正在使用 jemalloc。稍后我也会尝试使用 itbit。 CygWin 可能正在使用一些来自 Windows 的 Microsoft 分配器。
    • 我尝试使用 jemalloc(在我的 Arm CPU 笔记本电脑上),它运行良好,两种情况下的时间相同。
    猜你喜欢
    • 1970-01-01
    • 1970-01-01
    • 2022-08-17
    • 1970-01-01
    • 1970-01-01
    • 2012-05-21
    • 1970-01-01
    • 2015-10-04
    • 1970-01-01
    相关资源
    最近更新 更多