--- makedumpfile.ori 2015-07-06 11:56:11.300000000 -0400 +++ makedumpfile.c 2015-07-06 11:56:28.127000000 -0400 @@ -26,6 +26,42 @@ #include #include +unsigned long write_kdump_pages_parallel_cyclic_time = 0; +struct timeval write_kdump_pages_parallel_cyclic1, write_kdump_pages_parallel_cyclic2; +unsigned long loop_time = 0; +unsigned long consume_time = 0; +struct timeval loop1, loop2; +unsigned long check_time = 0; +struct timeval check1, check2; +struct timeval write1, write2; +unsigned long write_time; +struct timeval lock1, lock2; +unsigned long lock_time; +struct timeval hit1, hit2; +unsigned long hit_time; +struct timeval find1, find2; +unsigned long find_time; +struct timeval timea1, timea2; +unsigned long timea; +struct timeval timeb1, timeb2; +unsigned long filter_time[20]; +struct timeval filter1[20], filter2[20]; +unsigned long cp_time[20]; +struct timeval cp1[20], cp2[20]; +unsigned long compress_time[20]; +struct timeval compress_time1[20], compress_time2[20]; +unsigned long timeb; +unsigned long count1 = 0; +unsigned long count2 = 0; +unsigned long count3 = 0; +unsigned long count4 = 0; +unsigned long count5 = 0; +unsigned long count6 = 0; +unsigned long count7 = 0; +unsigned long count8 = 0; +unsigned long count9 = 0; + + struct symbol_table symbol_table; struct size_table size_table; struct offset_table offset_table; @@ -6919,6 +6955,17 @@ return TRUE; } +int compress2015(unsigned char *buf_out, unsigned long *size_out, unsigned char *buf, int page_size, int a, int thread_num) +{ +int ret; +gettimeofday(&compress_time1[thread_num], NULL); +ret = compress2(buf_out, size_out, buf, info->page_size, Z_BEST_SPEED); +gettimeofday(&compress_time2[thread_num], NULL); +compress_time[thread_num] += (compress_time2[thread_num].tv_sec - compress_time1[thread_num].tv_sec) * 1000000 + (compress_time2[thread_num].tv_usec - compress_time1[thread_num].tv_usec); + +return ret; +} + void * kdump_thread_function_cyclic(void *arg) { void *retval = PTHREAD_FAIL; @@ -6944,6 +6991,7 @@ unsigned long len_buf_out_snappy = snappy_max_compressed_length(info->page_size); #endif +int thread_num = kdump_thread_args->thread_num; buf = BUF_PARALLEL(kdump_thread_args->thread_num); buf_out = BUF_OUT_PARALLEL(kdump_thread_args->thread_num); @@ -7030,9 +7078,13 @@ mmap_cache)) goto fail; + +gettimeofday(&filter1[thread_num], NULL); filter_data_buffer_parallel(buf, pfn_to_paddr(pfn), info->page_size, &info->filter_mutex); +gettimeofday(&filter2[thread_num], NULL); +filter_time[thread_num] += (filter2[thread_num].tv_sec - filter1[thread_num].tv_sec) * 1000000 + (filter2[thread_num].tv_usec - filter1[thread_num].tv_usec); if ((info->dump_level & DL_EXCLUDE_ZERO) && is_zero_page(buf, info->page_size)) { @@ -7048,14 +7100,17 @@ size_out = kdump_thread_args->len_buf_out; if ((info->flag_compress & DUMP_DH_COMPRESSED_ZLIB) && ((size_out = kdump_thread_args->len_buf_out), - compress2(buf_out, &size_out, buf, + compress2015(buf_out, &size_out, buf, info->page_size, - Z_BEST_SPEED) == Z_OK) + Z_BEST_SPEED, thread_num) == Z_OK) && (size_out < info->page_size)) { page_data_buf[index].flags = DUMP_DH_COMPRESSED_ZLIB; page_data_buf[index].size = size_out; +gettimeofday(&cp1[thread_num], NULL); memcpy(page_data_buf[index].buf, buf_out, size_out); +gettimeofday(&cp2[thread_num], NULL); +cp_time[thread_num] += (cp2[thread_num].tv_sec - cp1[thread_num].tv_sec) * 1000000 + (cp2[thread_num].tv_usec - cp1[thread_num].tv_usec); #ifdef USELZO } else if (info->flag_lzo_support && (info->flag_compress @@ -7220,6 +7275,7 @@ gettimeofday(&last, NULL); while (consuming_pfn < end_pfn) { +gettimeofday(&loop1, NULL); index = consuming_pfn % page_data_num; gettimeofday(&new, NULL); @@ -7232,17 +7288,26 @@ * check pfn first without mutex locked to reduce the time * trying to lock the mutex */ - if (page_data_buf[index].pfn != consuming_pfn) + if (page_data_buf[index].pfn != consuming_pfn){ +gettimeofday(&loop2, NULL); +loop_time += (loop2.tv_sec - loop1.tv_sec) * 1000000 + (loop2.tv_usec - loop1.tv_usec); continue; +} +gettimeofday(&find1, NULL); +gettimeofday(&lock1, NULL); pthread_mutex_lock(&page_data_buf[index].mutex); +gettimeofday(&lock2, NULL); +lock_time += (lock2.tv_sec - lock1.tv_sec) * 1000000 + (lock2.tv_usec - lock1.tv_usec); + /* check whether the found one is ready to be consumed */ if (page_data_buf[index].pfn != consuming_pfn || page_data_buf[index].ready != 1) { goto unlock; } +gettimeofday(&hit1, NULL); if ((num_dumped % per) == 0) print_progress(PROGRESS_COPY, num_dumped, info->num_dumpable); @@ -7256,6 +7321,7 @@ num_dumped++; +gettimeofday(&write1, NULL); if (page_data_buf[index].zero == TRUE) { if (!write_cache(cd_header, pd_zero, sizeof(page_desc_t))) goto out; @@ -7278,8 +7344,17 @@ goto out; } + +gettimeofday(&write2, NULL); +write_time += (write2.tv_sec - write1.tv_sec) * 1000000 + (write2.tv_usec - write1.tv_usec); + unlock: pthread_mutex_unlock(&page_data_buf[index].mutex); +gettimeofday(&hit2, NULL); +gettimeofday(&find2, NULL); +hit_time += (hit2.tv_sec - hit1.tv_sec) * 1000000 + (hit2.tv_usec - hit1.tv_usec); +find_time += (find2.tv_sec - find1.tv_sec) * 1000000 + (find2.tv_usec - find1.tv_usec); + } ret = TRUE; @@ -7438,8 +7513,8 @@ size_out = len_buf_out; if ((info->flag_compress & DUMP_DH_COMPRESSED_ZLIB) && ((size_out = len_buf_out), - compress2(buf_out, &size_out, buf, info->page_size, - Z_BEST_SPEED) == Z_OK) + compress2015(buf_out, &size_out, buf, info->page_size, + Z_BEST_SPEED, 0) == Z_OK) && (size_out < info->page_size)) { pd.flags = DUMP_DH_COMPRESSED_ZLIB; pd.size = size_out; @@ -10314,6 +10389,11 @@ int main(int argc, char *argv[]) { + unsigned long total_time = 0; + struct timeval start_time, end_time; + gettimeofday(&start_time, NULL); + + int i, opt, flag_debug = FALSE; if ((info = calloc(1, sizeof(struct DumpInfo))) == NULL) { @@ -10328,7 +10408,6 @@ goto out; } initialize_tables(); - /* * By default, makedumpfile assumes that multi-cycle processing is * necessary to work in constant memory space. @@ -10642,5 +10721,21 @@ } free_elf_info(); + gettimeofday(&end_time, NULL); + total_time = (end_time.tv_sec - start_time.tv_sec) * 1000000 + (end_time.tv_usec - start_time.tv_usec); + MSG("lock time: %lds%ldus\n", lock_time / 1000000, lock_time % 1000000); + MSG("write time: %lds%ldus\n", write_time / 1000000, write_time % 1000000); + MSG("hit time: %lds%ldus\n", hit_time / 1000000, hit_time % 1000000); + MSG("find time: %lds%ldus\n", find_time / 1000000, find_time % 1000000); + MSG("loop_time: %lds%ldus\n", loop_time / 1000000, loop_time % 1000000); + MSG("thread consume_time: %lds%ldus\n", consume_time / 1000000, consume_time % 1000000); +for (i = 0; i < info->num_threads; i++){ + MSG("filter_time[%d]: %lds%ldus\n", i, filter_time[i] / 1000000, filter_time[i] % 1000000); + MSG("cp_time[%d]: %lds%ldus\n", i, cp_time[i] / 1000000, cp_time[i] % 1000000); + MSG("compress_time[%d]: %lds%ldus\n", i, compress_time[i] / 1000000, compress_time[i] % 1000000); +} + MSG("exec time: %lds%ldus\n", total_time / 1000000, total_time % 1000000); + + return retcd; }