Perf笔记(七)——perf trace

perf trace有类似于strace功能,可以实时监控程序的系统调用:

# perf trace ./a.out
 0.032 ( 0.002 ms): a.out/7673 brk(                                                                  ) = 0x1e6b000
 0.051 ( 0.005 ms): a.out/7673 access(filename: 0xb7c1cb00, mode: R                                  ) = -1 ENOENT No such file or directory
 0.063 ( 0.005 ms): a.out/7673 open(filename: 0xb7c1a7b7, flags: CLOEXEC                             ) = 3
 0.070 ( 0.002 ms): a.out/7673 fstat(fd: 3, statbuf: 0x7ffffb72bc80                                  ) = 0
 0.073 ( 0.004 ms): a.out/7673 mmap(len: 38436, prot: READ, flags: PRIVATE, fd: 3                    ) = 0x7f18b7e15000
 0.079 ( 0.001 ms): a.out/7673 close(fd: 3                                                           ) = 0
 0.087 ( 0.005 ms): a.out/7673 open(filename: 0xb7e21ec0, flags: CLOEXEC                             ) = 3
 0.093 ( 0.003 ms): a.out/7673 read(fd: 3, buf: 0x7ffffb72be28, count: 832                           ) = 832
 0.099 ( 0.002 ms): a.out/7673 fstat(fd: 3, statbuf: 0x7ffffb72bcc0                                  ) = 0
 0.102 ( 0.003 ms): a.out/7673 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f18b7e13000
 0.110 ( 0.004 ms): a.out/7673 mmap(len: 2283024, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3   ) = 0x7f18b79cf000
 0.116 ( 0.007 ms): a.out/7673 mprotect(start: 0x7f18b79fc000, len: 2093056                          ) = 0
 0.125 ( 0.005 ms): a.out/7673 mmap(addr: 0x7f18b7bfb000, len: 8192, prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 180224) = 0x7f18b7bfb000
 0.142 ( 0.002 ms): a.out/7673 close(fd: 3                                                           ) = 0
 0.153 ( 0.006 ms): a.out/7673 open(filename: 0xb7e134c0, flags: CLOEXEC                             ) = 3
 0.161 ( 0.003 ms): a.out/7673 read(fd: 3, buf: 0x7ffffb72bdf8, count: 832                           ) = 832
 0.165 ( 0.002 ms): a.out/7673 fstat(fd: 3, statbuf: 0x7ffffb72bc90                                  ) = 0
 0.169 ( 0.005 ms): a.out/7673 mmap(len: 2216432, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3   ) = 0x7f18b77b1000
......

Perf笔记(四)——profile应用程序

使用perf record命令可以profile应用程序  (编译程序要使用-g,推荐使用-g -O2

perf record program [args]

或者在程序启动以后,使用-p pid选项:

perf record -p pid

默认情况下,信息会存在perf.data文件里,使用perf report命令可以解析这个文件:

Capture

哪些函数占用CPU比较多,一目了然。

另外,在使用perf record时可以加--call-graph dwarf选项:

--call-graph
 Setup and enable call-graph (stack chain/backtrace) recording, implies -g.
 Default is "fp".

采样结果如下:

Capture

关于ChildrenSelf的含义,perf wiki给了一个详尽的解释。以下列代码为例:

void foo(void) {
    /* do something */
}

void bar(void) {
    /* do something */
    foo();
}

int main(void) {
    bar()
    return 0;
}

Self表示函数本身的overhead:如果foo函数的overhead60%,那么barSelf overhead就是40%(刨除foo所占部分)。因为foobar都是main的子函数,所以二者的overhead都要计算入mainChildren overhead

对于采用--call-graph dwarf选项生成的perf.data做出的火焰图如下:

Capture可以看到显示了完整的函数调用栈。

Perf笔记(三)——tiptop

Tiptop是一个Linux系统性能工具,它通过读取CPU硬件计数器的信息(比如cahche missexecuted instructions per cycle等等),使我们对程序的执行效率有了更清晰的认识:

Capture

Tiptop通过perf_event_open(http://man7.org/linux/man-pages/man2/perfeventopen.2.html)系统调用(2.6.31版本称为perf_counter_open)来完成读取硬件计数器信息:

int perf_event_open(struct perf_event_attr *attr,
                           pid_t pid, int cpu, int group_fd,
                           unsigned long flags);

attr用来指定需要关注哪些硬件计数器;pidcpu指定关注运行在哪些CPU的进程(线程);group_fd用来设定event group,创建group leader时,group_fd设为-1flags可以置为0

perf_event_open执行成功后会返回一个有效的文件描述符,后续可通过ioctlread系统调用对这个文件描述符进行操作,达到想要的目的。

uftrace工具介绍

uftrace是一个追踪和分析C/C++程序的工具,其灵感来自于Linux kernelftrace框架(项目主页:https://github.com/namhyung/uftrace)。

(1)安装。
uftrace依赖于elfutils项目中的libelf,所以要首先安装libelf,而uftrace的安装则很简单:

# git clone https://github.com/namhyung/uftrace.git
# cd uftrace
# make
# make install

(2)使用。
以这个简单程序(test.cpp)为例:

#include <cstdio>

class A {
public:
        A() {printf("A is created\n");}
        ~A() {printf("A is destroyed\n");}
};

int main() {
        A a;
        return 0;
}

uftrace要求编译时指定-pg-finstrument-functions选项:

# g++ -pg test.cpp

编译成功后,通过uftrace工具可以对程序进行分析:

# uftrace a.out
A is created
A is destroyed
# DURATION    TID     FUNCTION
   4.051 us [ 8083] | __cxa_atexit();
            [ 8083] | main() {
            [ 8083] |   A::A() {
  13.340 us [ 8083] |     puts();
  17.321 us [ 8083] |   } /* A::A */
            [ 8083] |   A::~A() {
   1.815 us [ 8083] |     puts();
   4.679 us [ 8083] |   } /* A::~A */
  26.051 us [ 8083] | } /* main */

可以看到输出结果包含了程序的运行流程以及各个函数的执行时间。另外也可以使用-k选项追踪内核的相关函数:

# uftrace -k a.out
A is created
A is destroyed
# DURATION    TID     FUNCTION
   1.048 us [ 8091] | __cxa_atexit();
   0.978 us [ 8091] | sys_clock_gettime();
   0.768 us [ 8091] | main();
            [ 8091] | sys_clock_gettime() {
            [ 8091] |   A::A() {
   0.699 us [ 8091] |   } /* sys_clock_gettime */
            [ 8091] |   sys_clock_gettime() {
            [ 8091] |     puts() {
   0.768 us [ 8091] |     } /* sys_clock_gettime */
            [ 8091] |     sys_newfstat() {
   1.466 us [ 8091] |       smp_irq_work_interrupt();
   4.819 us [ 8091] |     } /* sys_newfstat */
   3.422 us [ 8091] |     __do_page_fault();
            [ 8091] |     sys_clock_gettime() {
   1.327 us [ 8091] |       smp_irq_work_interrupt();
   3.701 us [ 8091] |     } /* puts */
......  

通常我们需要把运行结果保存下来,便于以后分析,这时可以使用uftracerecord功能:

# uftrace record a.out
A is created
A is destroyed
# ls
a.out  test.cpp  uftrace.data

可以看到在当前目录下多了一个uftrace.data的文件夹,里面记录了关于这次程序运行的信息,随后就可以对程序进行分析了。举个例子,可以使用uftracereplay功能对程序的运行进行一遍“回看”:

# uftrace replay
# DURATION    TID     FUNCTION
   3.980 us [ 8104] | __cxa_atexit();
            [ 8104] | main() {
            [ 8104] |   A::A() {
  30.660 us [ 8104] |     puts();
  34.781 us [ 8104] |   } /* A::A */
            [ 8104] |   A::~A() {
  27.378 us [ 8104] |     puts();
  30.591 us [ 8104] |   } /* A::~A */
  69.632 us [ 8104] | } /* main */

综上所述,uftrace在下面这两个方面可以给我们很大帮助:
(1)了解程序的执行流程;
(2)度量函数的运行时间,确定热点。
感兴趣的朋友不妨亲自一试!

time和/usr/bin/time

当我在bash中敲入time命令时,运行的其实是bash内置的time命令:

$ time

real    0m0.000s
user    0m0.000s
sys     0m0.000s
$ type time
time is a shell keyword

这个time命令有一个-p选项,表示以posix格式输出:

$ time -p
real 0.00
user 0.00
sys 0.00

除此以外,还有一个time命令。不过我当前的机器并没有安装这个程序:

$ which time
which: no time in (/home/xiaonan/.cargo/bin:/usr/local/sbin:/usr/local/bin:/usr/bin:/opt/cuda/bin:/usr/lib/jvm/default/bin:/usr/bin/site_perl:/usr/bin/vendor_perl:/usr/bin/core_perl)

安装一下,对比bash内置的time命令:

$ sudo pacman -S time
$ type time
time is a shell keyword
$ which time
/usr/bin/time

单独运行“/usr/bin/time -p”,只会输出命令的帮助选项:

$ /usr/bin/time -p
Usage: /usr/bin/time [-apvV] [-f format] [-o file] [--append] [--verbose]
       [--portability] [--format=format] [--output=file] [--version]
       [--help] command [arg...]

需要加上具体的需要度量时间的命令:

$ /usr/bin/time -p echo

real 0.00
user 0.00
sys 0.00

此外也可以给出命令执行的详细信息:

$ /usr/bin/time -v echo

    Command being timed: "echo"
    User time (seconds): 0.00
    System time (seconds): 0.00
    Percent of CPU this job got: 0%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.00
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 1536
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 0
    Minor (reclaiming a frame) page faults: 70
    Voluntary context switches: 1
    Involuntary context switches: 1
    Swaps: 0
    File system inputs: 0
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

参考资料:
/usr/bin/time: not the command you think you know

Linux系统查看可用内存

http://www.linuxatemyram.com/提到使用free命令查看Linux系统使用内存时,used一项会把当前cache的大小也会加进去,这样会造成free这一栏显示的内存特别少:

$ free -m
               total        used        free      shared  buff/cache   available
Mem:           1504        1491          13           0         855      869
Swap:          2047           6        2041

可是实际上,cache根据应用程序的需要是可以回收利用的,因此free这一栏并不能真实地表现有多少“可以使用”的内存。实际系统可用内存应该以available数据为准。

linuxatemyram所提到的free命令也许是比较老的版本,我尝试了RHEL 7.2Ubuntu 16.04Arch Linux3Linux发行版,均没有出现used包含cache的情况:

$ free -m
              total        used        free      shared  buff/cache   available
Mem:          64325       47437        3150        1860       13737       14373

另外,从man free命令中也可以得到,目前计算used的值是要减掉freebuff/cache的:

used Used memory (calculated as total – free – buffers – cache)

可以使用-w命令行选项得到buffcache各自使用的数量:

$ free -wm
              total        used        free      shared     buffers       cache   available
Mem:          64325       48287        2476        1859        1430       12131       13524

需要注意的是,free表示的是当前完全没有被程序使用的内存;而cache在有需要时,是可以被释放出来以供其它进程使用的(当然,并不是所有cache都可以释放,比如当前被用作ramfs的内存)。而available才真正表明系统目前可以提供给应用程序使用的内存。/proc/meminfo3.14内核版本开始提供MemAvailable的值;在2.6.27~3.14版本之间,是free程序自己计算available的值;早于2.6.27版本,available的值则同free一样。

参考资料:
Understanding output of free in Ubuntu 16.04
How can I get the amount of available memory portably across distributions?

HE-API项目简介

HE-API提供一个统一的接口,屏蔽了底层使用的SHE library的细节,使对加密不是很了解的人也可以轻松掌握(代码在这里)。HE-API目前只支持HElib,通过使用不同的编译选项(FXPTBINARY)来生成支持不同数据类型的库:helib.a.fxpthelib.a.binaryhelib.a.ulong。下面以testInteger函数为例,来分析如何使用:

template <unsigned long nb_tests>
int testInteger() {
  // Determine if the test should run
  #ifdef BINARY
  unsigned long run = HE::supports_bit_encryption;
  #else
  unsigned long run = HE::supports_unsigned_encryption;
  #endif

  if (!run) {
    return 0;
  }

  timing t;

  gmp_randclass prng(gmp_randinit_default);
//  prng.seed(0);
  prng.seed(time(NULL)); // To set different seeds

  void* parameters = nullptr;
  void* sk = nullptr;
  void* pk = nullptr;
  void* evk = nullptr;

  // Init
  t.start();
  HE::init(&parameters);
  t.stop("Init");

  // Keygen
  t.start();
  HE::keygen(parameters, &sk, &pk, &evk);
  t.stop("Keygen");
  // HE::serialize_sk("sk.bin", sk);
  // std::cout << "serialized?" << std::endl;

  // Random messages
  unsigned long* messages1 = new unsigned long[nb_tests];
  unsigned long* messages2 = new unsigned long[nb_tests];
  for (unsigned long i = 0; i < nb_tests; i++) {
    messages1[i] =
        mpz_class(prng.get_z_range(HE::plaintext_modulus)).get_ui();
    messages2[i] =
        mpz_class(prng.get_z_range(HE::plaintext_modulus)).get_ui();
  }

  // Encrypt
  void** ciphertexts1 = new void* [nb_tests];
  void** ciphertexts2 = new void* [nb_tests];
  t.start();
  for (unsigned long i = 0; i < nb_tests; i++) {
    HE::encryptInteger(pk, &(ciphertexts1[i]), messages1[i]);
    HE::encryptInteger(pk, &(ciphertexts2[i]), messages2[i]);
  }
  t.stop("Encrypt Integer", nb_tests * 2);

  // Decrypt
  unsigned long* messages1_decrypted = new unsigned long[nb_tests];
  unsigned long* messages2_decrypted = new unsigned long[nb_tests];
  t.start();
  for (unsigned long i = 0; i < nb_tests; i++) {
    HE::decryptInteger(sk, pk, ciphertexts1[i], &(messages1_decrypted[i]));
    HE::decryptInteger(sk, pk, ciphertexts2[i], &(messages2_decrypted[i]));
  }
  t.stop("Decrypt Integer", nb_tests * 2);

  // Correctness of decryption
  for (unsigned long i = 0; i < nb_tests; i++) {
    assert(messages1[i] == messages1_decrypted[i]);
    assert(messages2[i] == messages2_decrypted[i]);
  }

  // Homomorphic additions
  unsigned long* messages_added = new unsigned long[nb_tests];
  for (unsigned long i = 0; i < nb_tests; i++) {
    messages_added[i] = (messages1[i] + messages2[i]) % HE::plaintext_modulus;
  }
  void** ciphertexts_added = new void* [nb_tests];
  t.start();
  for (unsigned long i = 0; i < nb_tests; i++) {
    HE::add(pk, evk, &(ciphertexts_added[i]), ciphertexts1[i], ciphertexts2[i]);
  }
  t.stop("Homomorphic Addition", nb_tests);

  // Correctness of addition
  unsigned long* messages_added_decrypted = new unsigned long[nb_tests];
  for (unsigned long i = 0; i < nb_tests; i++) {
    HE::decryptInteger(sk, pk, ciphertexts_added[i],
                     &(messages_added_decrypted[i]));
    assert(messages_added_decrypted[i] == messages_added[i]);
  }

  // Homomorphic multiplications
  unsigned long* messages_multiplied = new unsigned long[nb_tests];
  for (unsigned long i = 0; i < nb_tests; i++) {
    messages_multiplied[i] = (messages1[i] * messages2[i]) % HE::plaintext_modulus;
  }
  void** ciphertexts_multiplied = new void* [nb_tests];
  t.start();
  for (unsigned long i = 0; i < nb_tests; i++) {
    HE::mul(pk, evk, &(ciphertexts_multiplied[i]), ciphertexts1[i],
          ciphertexts2[i]);
  }
  t.stop("Homomorphic Multiplication", nb_tests);

  // Correctness of multiplication
  unsigned long* messages_multiplied_decrypted = new unsigned long[nb_tests];
  for (unsigned long i = 0; i < nb_tests; i++) {
    HE::decryptInteger(sk, pk, ciphertexts_multiplied[i],
                     &(messages_multiplied_decrypted[i]));
    assert(messages_multiplied_decrypted[i] == messages_multiplied[i]);
  }

  delete[] messages1;
  delete[] messages2;
  delete[] messages_added;
  delete[] messages_added_decrypted;
  delete[] messages_multiplied;
  delete[] messages_multiplied_decrypted;

  for(long i=0; i< nb_tests; i++)
  {
      HE::freeup_ciphertext(pk,ciphertexts1[i]);
      HE::freeup_ciphertext(pk,ciphertexts2[i]);
      HE::freeup_ciphertext(pk,ciphertexts_added[i]);
      HE::freeup_ciphertext(pk,ciphertexts_multiplied[i]);
  }

  delete[] ciphertexts1;
  delete[] ciphertexts2;
  delete[] ciphertexts_added;
  delete[] ciphertexts_multiplied;

  HE::freeup_keys(parameters,sk,pk,evk);

  return 0;
}

(1)HE-API使用了gmp项目:
a)gmp_randclass类用来生成随机数:

......
gmp_randclass prng(gmp_randinit_default);
//  prng.seed(0);
prng.seed(time(NULL)); // To set different seeds
......
messages1[i] =
        mpz_class(prng.get_z_range(HE::plaintext_modulus)).get_ui();
messages2[i] =
        mpz_class(prng.get_z_range(HE::plaintext_modulus)).get_ui();

b)mpz_class用来表示整数。get_ui()返回mpz_class的最低位的unsigned long。以Binary为例,mpz_class(prng.get_z_range(HE::plaintext_modulus)).get_ui();随机返回01

(2)另外就是需要注意加法和乘法时的取模运算:

......
messages_added[i] = (messages1[i] + messages2[i]) % HE::plaintext_modulus;
......
messages_multiplied[i] = (messages1[i] * messages2[i]) % HE::plaintext_modulus;

仍以Binary为例,此时PLAINTEXT_MODULUS的值为2,即要对2取模。操作数是1bit,取值为01,加密结果对应的也是01

P.S.,在编译HEAT使用HElib时可能会遇到错误,具体参考这个issue