[김준석] perf 성능분석보고서

[kimjun2773]

1. 5가지 서로다른 sudoku 소스를 각각 실행해 본다.

.fxn
컴파일>$ g++ -o sudoku sudoku.c
실행> $ ./sudoku
+---------+---------+---------+
| 1 2 3 | 4 5 6 | 7 8 9 |
| 4 5 6 | 7 8 9 | 1 2 3 |
| 7 8 9 | 1 2 3 | 4 5 6 |
+---------+---------+---------+
| 2 1 4 | 3 6 5 | 8 9 7 |
| 3 6 5 | 8 9 7 | 2 1 4 |
| 8 9 7 | 2 1 4 | 3 6 5 |
+---------+---------+---------+
| 5 3 1 | 6 4 2 | 9 7 8 |
| 6 4 2 | 9 7 8 | 5 3 1 |
| 9 7 8 | 5 3 1 | 6 4 2 |
+---------+---------+---------+

.imphasing
컴파일> $ make
실행> $ ./solver < sample_easy
534678912672195348198342567859761423426853791713924856961537284287419635345286179

.hmgle
컴파일> $ make
실행> $ ./sudoku_solver < test1.txt
571864923628739154439512678362947581194358267857126349715283496943675812286491735

.rg3
컴파일> $ gcc -o sudoku sudoku.c
실행> $ ./sudoku < quiz
5 3 4 6 7 8 9 1 2
6 7 2 1 9 5 3 4 8
1 9 8 3 4 2 5 6 7
8 5 9 7 6 1 4 2 3
4 2 6 8 5 3 7 9 1
7 1 3 9 2 4 8 5 6
9 6 1 5 3 7 2 8 4
2 8 7 4 1 9 6 3 5
3 4 5 2 8 6 1 7 9

.geeksforgeeks
컴파일> $ g++ -o sudoku sudoku.c
실행> $ ./sudoku
3 1 6 5 7 8 4 9 2
5 2 9 1 3 4 7 6 8
4 8 7 6 2 9 5 3 1
2 6 3 4 1 5 9 8 7
9 7 4 8 6 3 1 2 5
8 5 1 7 9 2 6 4 3
1 3 8 9 4 7 2 5 6
6 9 2 3 5 1 8 7 4
7 4 5 2 8 6 3 1 9

[kimjun2773]

2. perf record, stat을 사용하여 아래 event 뿐만 아니라 여러 event로 초점을 바꿔가며 성능을 분석한다.

.fxn
$ sudo perf stat -e cache-misses ./sudoku
+---------+---------+---------+
| 1 2 3 | 4 5 6 | 7 8 9 |
| 4 5 6 | 7 8 9 | 1 2 3 |
| 7 8 9 | 1 2 3 | 4 5 6 |
+---------+---------+---------+
| 2 1 4 | 3 6 5 | 8 9 7 |
| 3 6 5 | 8 9 7 | 2 1 4 |
| 8 9 7 | 2 1 4 | 3 6 5 |
+---------+---------+---------+
| 5 3 1 | 6 4 2 | 9 7 8 |
| 6 4 2 | 9 7 8 | 5 3 1 |
| 9 7 8 | 5 3 1 | 6 4 2 |
+---------+---------+---------+

Performance counter stats for './sudoku':

        18,682      cache-misses                                            

   0.011573455 seconds time elapsed

분석:> 같은 프로그램임에도 불구하고 다른 결과가 나왔다.
하드웨어에서 성능분석을 위한 레지스터등을 지원 하지만 정확히 모든시간대의 모든 CPU 상황을 추적하는것이 아니고 오버헤드 등을 낮추기위해 순간순간 스냅샷을 저장하는 형식으로 동작하여 같은결과가 나오지 않을수 있고 OS 내부의 정책에 따라 프로그램이 같은 상황에서 돌아가지 않기때문에 (스케줄러 등..) 다른 결과가 나왔다고 생각한다.

.geeksforgeeks
$ sudo perf stat -e cpu-cycles,branch-misses ./sudoku
3 1 6 5 7 8 4 9 2
5 2 9 1 3 4 7 6 8
4 8 7 6 2 9 5 3 1
2 6 3 4 1 5 9 8 7
9 7 4 8 6 3 1 2 5
8 5 1 7 9 2 6 4 3
1 3 8 9 4 7 2 5 6
6 9 2 3 5 1 8 7 4
7 4 5 2 8 6 3 1 9

Performance counter stats for './sudoku':

     8,554,258      cpu-cycles                                              
        68,681      branch-misses                                           

   0.016355020 seconds time elapsed

분석> 이번에는 이벤트 를 두개로 추가하여 분석해 보았다. 분석할 이벤트를 1개로 했을 때와 2개로 했을때 성능 분석 프로그램의 오버헤드로 인한 프로그램 구동시간의 증가가 있을까 해서 옵션을 두개일때와 한개일때를 각각 구동해보니 오히려 2개일때 실행속도가 미묘하게 짧은 것으로 보아 성능분석 프로그램은 구동되는 프로그램에 영향을 끼치지 않고 분석 하는것을 확인 할 수 있었다. 역시 분석마다 미묘하게 이벤트의 상세한 값들은 차이가 있었지만 큰 차이는 없었다. 컴퓨터 내에 프로세스가 많아 CPU가 바쁠때에 분석하려는 프로세스의 CPU 사이클수에 영향을 미치는가 알아보아야 겠다.

.hmgle
$ sudo perf stat -e cpu-cycles:u,cpu-cycles:k ./sudoku_solver < test1.txt
571864923628739154439512678362947581194358267857126349715283496943675812286491735

Performance counter stats for './sudoku_solver':

    20,501,672      cpu-cycles:u                                                  (48.49%)
     2,375,622      cpu-cycles:k                                                  (64.57%)

   0.040696822 seconds time elapsed

분석> 이벤트 하나를 레벨별로 얼마나 발생했는지 나누어 분석해 보았다 옆의 퍼센트는 해당레벨에서 발생하는 싸이클당 분석하고자 하는 프로세스의 이벤트 발생 비율을 나타내는것 같다. 유저레벨에서는 운영체제에서 돌아가고 있는 모든 프로세스 중에서 48퍼센트의 씨피유 싸이클을 차지했다는 의미인것 같다.

.imphasing
$ sudo perf record -e branch-misses ./solver < sample_easy
$ sudo perf report
Samples: 59 of event 'branch-misses', Event count (approx.): 70675
Overhead Command Shared Object Symbol
33.67% solver solver [.] vertex_must_be
10.22% solver solver [.] array_contains
8.15% solver solver [.] color_graph
7.50% solver libc-2.19.so [.] _int_malloc
3.30% solver [kernel.kallsyms] [k] __alloc_fd
3.25% solver solver [.] edges_disallow_color
3.21% solver [kernel.kallsyms] [k] __fget
3.18% solver libc-2.19.so [.] _int_free
3.00% solver [kernel.kallsyms] [k] down_write
2.87% solver ld-2.19.so [.] do_lookup_x
2.84% solver [kernel.kallsyms] [k] vm_munmap
2.69% solver libc-2.19.so [.] _dl_addr
2.65% solver [kernel.kallsyms] [k] filemap_map_pages
2.37% solver [kernel.kallsyms] [k] mmiocpy
2.26% solver [unknown] [.] 0xffff0fe0
2.12% solver ld-2.19.so [.] strcmp
1.63% solver [kernel.kallsyms] [k] do_mmap
1.56% solver solver [.] free_graph
1.53% solver [kernel.kallsyms] [k] unmap_single_vma
1.47% solver [kernel.kallsyms] [k] __fput
0.43% solver [kernel.kallsyms] [k] get_page_from_freelist
0.10% perf [kernel.kallsyms] [k] perf_event_exec

분석> 이번에는 perf stat 이 아닌 perf record 를 통해 상세히 분석해 보았다. branch-misses이벤트에 대해 분석했고 -a 옵션이아니라 프로세스 하나에 대해 분석 했다. 실행되는 함수중 유저레벨의 함수 vertex_must_be에서 가장 많이 발생 하였다 record 에선 상요되는 커널함수에서의 이벤트 발생도 찾아준다는것을 알게 되었다. [k] 기호가 있는 함수는 커널의 함수 인것 같다.