最近在优化一个脚本的时候发现
file_put_contents($file_done, “\n”.$num);
比
file_put_contents($file_done, “\n”.$num, FILE_APPEND);
慢100倍,有啥坑?
然后检查了php中file_put_contents是的实现源码,没有发现什么会很慢的处理,发现直接调用的open系统调用
然后测试open系统调用
test1.c
#include <stdio.h>
#include <unistd.h>
#include <fcntl.h>
int main (int argc, const char *argv[]) {
int fd;
char buf[64] = "abc";
if (!argv[1]) {
printf("please input a file");
return 0;
}
int i = 0;
for (i = 0; i < 1000; i++) {
fd = open(argv[1], O_RDWR|O_TRUNC|O_CREAT, 0666);
//fseek(fd, 0L, SEEK_SET);
write(fd, buf, 64);
close(fd);
}
return 0;
}
#include <unistd.h>
#include <fcntl.h>
int main (int argc, const char *argv[]) {
int fd;
char buf[64] = "abc";
if (!argv[1]) {
printf("please input a file");
return 0;
}
int i = 0;
for (i = 0; i < 1000; i++) {
fd = open(argv[1], O_RDWR|O_TRUNC|O_CREAT, 0666);
//fseek(fd, 0L, SEEK_SET);
write(fd, buf, 64);
close(fd);
}
return 0;
}
test2.c
#include <stdio.h>
#include <unistd.h>
#include <fcntl.h>
int main (int argc, const char *argv[]) {
int fd;
char buf[64] = "abc";
if (!argv[1]) {
printf("please input a file");
return 0;
}
int i = 0;
for (i = 0; i < 1000; i++) {
fd = open(argv[1], O_RDWR|O_CREAT|O_APPEND, 0666);
write(fd, buf, 64);
close(fd);
}
return 0;
}
#include <unistd.h>
#include <fcntl.h>
int main (int argc, const char *argv[]) {
int fd;
char buf[64] = "abc";
if (!argv[1]) {
printf("please input a file");
return 0;
}
int i = 0;
for (i = 0; i < 1000; i++) {
fd = open(argv[1], O_RDWR|O_CREAT|O_APPEND, 0666);
write(fd, buf, 64);
close(fd);
}
return 0;
}
测试结果
[root@localhost ~]# time ./test1 a
real 0m0.410s
user 0m0.001s
sys 0m0.096s
real 0m0.410s
user 0m0.001s
sys 0m0.096s
[root@localhost ~]# time ./test2 b
real 0m0.004s
user 0m0.000s
sys 0m0.003s
real 0m0.004s
user 0m0.000s
sys 0m0.003s
果然慢100倍,看来问题在这块,然后呢,发现对应的open、write、close都花费更多的时间
[root@localhost ~]# strace -c ./test1 a
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
69.00 0.067664 68 1002 close
24.13 0.023666 24 1002 open
6.86 0.006727 7 1000 write
0.00 0.000000 0 1 read
0.00 0.000000 0 2 fstat
0.00 0.000000 0 7 mmap
0.00 0.000000 0 4 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.098057 3023 1 total
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
69.00 0.067664 68 1002 close
24.13 0.023666 24 1002 open
6.86 0.006727 7 1000 write
0.00 0.000000 0 1 read
0.00 0.000000 0 2 fstat
0.00 0.000000 0 7 mmap
0.00 0.000000 0 4 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.098057 3023 1 total
[root@localhost ~]# strace -c ./test2 b
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
39.09 0.001749 2 1002 open
36.43 0.001630 2 1000 write
24.47 0.001095 1 1002 close
0.00 0.000000 0 1 read
0.00 0.000000 0 2 fstat
0.00 0.000000 0 7 mmap
0.00 0.000000 0 4 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.004474 3023 1 total
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
39.09 0.001749 2 1002 open
36.43 0.001630 2 1000 write
24.47 0.001095 1 1002 close
0.00 0.000000 0 1 read
0.00 0.000000 0 2 fstat
0.00 0.000000 0 7 mmap
0.00 0.000000 0 4 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 1 brk
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.004474 3023 1 total
查呀查呀查呀查
用perf工具分析程序分析了一下
[root@localhost ~]# perf record -e cpu-clock -g ./test1 a
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.100 MB perf.data (364 samples) ]
[root@localhost ~]# perf report
Samples: 364 of event 'cpu-clock', Event count (approx.): 91000000
- 100.00% 0.00% test1 libc-2.17.so [.] __libc_start_main
- __libc_start_main
- 97.25% __GI___libc_close
int_signal
do_notify_resume
task_work_run
____fput
__fput
xfs_file_release
xfs_release
filemap_flush
__filemap_fdatawrite_range
do_writepages
- xfs_vm_writepages
- 94.78% xfs_submit_ioend.isra.16
submit_bio
- generic_make_request
- 94.51% blk_queue_bio
__blk_run_queue
- scsi_request_fn
- scsi_dispatch_cmd
mptspi_qcmd
mptscsih_qcmd
mpt_put_msg_frame
+ 1.92% write_cache_pages
- 1.92% __GI___libc_open
system_call_fastpath
sys_open
do_sys_open
do_filp_open
path_openat
do_last
do_truncate
notify_change
xfs_vn_setattr
- xfs_setattr_size
- 1.10% xfs_itruncate_extents
0.55% xfs_bmap_finish
+ 0.82% truncate_setsize
- 0.82% __GI___libc_write
system_call_fastpath
sys_write
vfs_write
do_sync_write
xfs_file_aio_write
xfs_file_buffered_aio_write
generic_file_buffered_write
- xfs_vm_write_begin
0.55% __memset
+ 97.25% 0.00% test1 libc-2.17.so [.] __GI___libc_close
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] int_signal
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] do_notify_resume
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] task_work_run
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] ____fput
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] __fput
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] xfs_file_release
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] xfs_release
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] filemap_flush
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] __filemap_fdatawrite_range
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] do_writepages
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] xfs_vm_writepages
+ 95.33% 0.27% test1 [kernel.kallsyms] [k] scsi_request_fn
+ 95.33% 0.00% test1 [kernel.kallsyms] [k] __blk_run_queue
+ 95.05% 94.78% test1 [kernel.kallsyms] [k] mpt_put_msg_frame
+ 95.05% 0.27% test1 [kernel.kallsyms] [k] submit_bio
+ 95.05% 0.00% test1 [kernel.kallsyms] [k] scsi_dispatch_cmd
+ 95.05% 0.00% test1 [kernel.kallsyms] [k] mptspi_qcmd
+ 95.05% 0.00% test1 [kernel.kallsyms] [k] mptscsih_qcmd
+ 94.78% 0.00% test1 [kernel.kallsyms] [k] xfs_submit_ioend.isra.16
+ 94.78% 0.00% test1 [kernel.kallsyms] [k] generic_make_request
+ 94.51% 0.00% test1 [kernel.kallsyms] [k] blk_queue_bio
+ 2.75% 0.00% test1 [kernel.kallsyms] [k] system_call_fastpath
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] write_cache_pages
+ 1.92% 0.27% test1 [kernel.kallsyms] [k] xfs_do_writepage
+ 1.92% 0.00% test1 libc-2.17.so [.] __GI___libc_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] sys_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_sys_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_filp_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] path_openat
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_last
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_truncate
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] notify_change
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] xfs_vn_setattr
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] xfs_setattr_size
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_map_blocks
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_iomap_write_allocate
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_bmapi_write
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_alloc
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_btalloc
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_vextent
+ 1.37% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_ag_vextent
+ 1.37% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_ag_vextent_near
+ 1.10% 0.00% test1 [kernel.kallsyms] [k] xfs_itruncate_extents
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_log_force
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] _xfs_log_force
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xlog_state_release_iclog
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xlog_sync
+ 0.82% 0.00% test1 libc-2.17.so [.] __GI___libc_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] truncate_setsize
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xlog_bdstrat
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] sys_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] truncate_pagecache
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_buf_submit
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] _xfs_buf_ioapply
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] truncate_inode_pages_range
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] vfs_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] blk_finish_plug
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] do_sync_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] blk_flush_plug_list
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_file_aio_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] queue_unplugged
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_file_buffered_aio_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] generic_file_buffered_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_vm_write_begin
0.55% 0.27% test1 [kernel.kallsyms] [k] _xfs_buf_find
+ 0.55% 0.55% test1 [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_finish
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_fix_freelist
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_read_agf
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_read_agf
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_trans_read_buf_map
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] __pagevec_release
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_buf_read_map
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_buf_get_map
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_perag_get
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_btree_insrec
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_extent_busy_trim
0.27% 0.27% test1 [kernel.kallsyms] [k] finish_task_switch
0.27% 0.27% test1 [mptbase] [k] mpt_put_msg_frame
0.27% 0.27% test1 [kernel.kallsyms] [k] _cond_resched
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_vm_releasepage
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_cil_prepare_item.isra.2
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_iext_bno_to_ext
0.27% 0.27% test1 [kernel.kallsyms] [k] get_page_from_freelist
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_trans_log_efi_extent
0.27% 0.00% test1 [kernel.kallsyms] [k] wait_on_page_bit
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_trans_free_extent
0.27% 0.00% test1 [kernel.kallsyms] [k] __wait_on_bit
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_free_extent
0.27% 0.00% test1 [kernel.kallsyms] [k] bit_wait_io
0.27% 0.00% test1 [kernel.kallsyms] [k] io_schedule
0.27% 0.00% test1 [kernel.kallsyms] [k] dm_make_request
0.27% 0.00% test1 [kernel.kallsyms] [k] io_schedule_timeout
0.27% 0.00% test1 [kernel.kallsyms] [k] truncate_inode_page
0.27% 0.00% test1 [kernel.kallsyms] [k] __split_and_process_bio
0.27% 0.00% test1 [kernel.kallsyms] [k] __xfs_trans_roll
0.27% 0.00% test1 [kernel.kallsyms] [k] do_invalidatepage
0.27% 0.00% test1 [kernel.kallsyms] [k] grab_cache_page_write_begin
0.27% 0.00% test1 [kernel.kallsyms] [k] schedule_timeout
0.27% 0.00% test1 [kernel.kallsyms] [k] __clone_and_map_data_bio
0.27% 0.00% test1 [kernel.kallsyms] [k] __page_cache_alloc
0.27% 0.00% test1 [kernel.kallsyms] [k] __xfs_trans_commit
0.27% 0.00% test1 [kernel.kallsyms] [k] lru_add_drain_cpu
0.27% 0.00% test1 [kernel.kallsyms] [k] schedule
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_fixup_trees
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_bunmapi
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_vm_invalidatepage
0.27% 0.00% test1 [kernel.kallsyms] [k] __schedule
0.27% 0.00% test1 [kernel.kallsyms] [k] alloc_pages_current
0.27% 0.00% test1 [kernel.kallsyms] [k] bio_alloc_bioset
0.27% 0.00% test1 [kernel.kallsyms] [k] block_invalidatepage_range
0.27% 0.00% test1 [kernel.kallsyms] [k] pagevec_lru_move_fn
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_compute_aligned
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_search_extents
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_btree_insert
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_log_commit_cil
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.100 MB perf.data (364 samples) ]
[root@localhost ~]# perf report
Samples: 364 of event 'cpu-clock', Event count (approx.): 91000000
- 100.00% 0.00% test1 libc-2.17.so [.] __libc_start_main
- __libc_start_main
- 97.25% __GI___libc_close
int_signal
do_notify_resume
task_work_run
____fput
__fput
xfs_file_release
xfs_release
filemap_flush
__filemap_fdatawrite_range
do_writepages
- xfs_vm_writepages
- 94.78% xfs_submit_ioend.isra.16
submit_bio
- generic_make_request
- 94.51% blk_queue_bio
__blk_run_queue
- scsi_request_fn
- scsi_dispatch_cmd
mptspi_qcmd
mptscsih_qcmd
mpt_put_msg_frame
+ 1.92% write_cache_pages
- 1.92% __GI___libc_open
system_call_fastpath
sys_open
do_sys_open
do_filp_open
path_openat
do_last
do_truncate
notify_change
xfs_vn_setattr
- xfs_setattr_size
- 1.10% xfs_itruncate_extents
0.55% xfs_bmap_finish
+ 0.82% truncate_setsize
- 0.82% __GI___libc_write
system_call_fastpath
sys_write
vfs_write
do_sync_write
xfs_file_aio_write
xfs_file_buffered_aio_write
generic_file_buffered_write
- xfs_vm_write_begin
0.55% __memset
+ 97.25% 0.00% test1 libc-2.17.so [.] __GI___libc_close
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] int_signal
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] do_notify_resume
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] task_work_run
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] ____fput
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] __fput
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] xfs_file_release
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] xfs_release
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] filemap_flush
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] __filemap_fdatawrite_range
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] do_writepages
+ 97.25% 0.00% test1 [kernel.kallsyms] [k] xfs_vm_writepages
+ 95.33% 0.27% test1 [kernel.kallsyms] [k] scsi_request_fn
+ 95.33% 0.00% test1 [kernel.kallsyms] [k] __blk_run_queue
+ 95.05% 94.78% test1 [kernel.kallsyms] [k] mpt_put_msg_frame
+ 95.05% 0.27% test1 [kernel.kallsyms] [k] submit_bio
+ 95.05% 0.00% test1 [kernel.kallsyms] [k] scsi_dispatch_cmd
+ 95.05% 0.00% test1 [kernel.kallsyms] [k] mptspi_qcmd
+ 95.05% 0.00% test1 [kernel.kallsyms] [k] mptscsih_qcmd
+ 94.78% 0.00% test1 [kernel.kallsyms] [k] xfs_submit_ioend.isra.16
+ 94.78% 0.00% test1 [kernel.kallsyms] [k] generic_make_request
+ 94.51% 0.00% test1 [kernel.kallsyms] [k] blk_queue_bio
+ 2.75% 0.00% test1 [kernel.kallsyms] [k] system_call_fastpath
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] write_cache_pages
+ 1.92% 0.27% test1 [kernel.kallsyms] [k] xfs_do_writepage
+ 1.92% 0.00% test1 libc-2.17.so [.] __GI___libc_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] sys_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_sys_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_filp_open
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] path_openat
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_last
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] do_truncate
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] notify_change
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] xfs_vn_setattr
+ 1.92% 0.00% test1 [kernel.kallsyms] [k] xfs_setattr_size
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_map_blocks
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_iomap_write_allocate
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_bmapi_write
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_alloc
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_btalloc
+ 1.65% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_vextent
+ 1.37% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_ag_vextent
+ 1.37% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_ag_vextent_near
+ 1.10% 0.00% test1 [kernel.kallsyms] [k] xfs_itruncate_extents
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_log_force
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] _xfs_log_force
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xlog_state_release_iclog
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xlog_sync
+ 0.82% 0.00% test1 libc-2.17.so [.] __GI___libc_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] truncate_setsize
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xlog_bdstrat
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] sys_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] truncate_pagecache
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_buf_submit
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] _xfs_buf_ioapply
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] truncate_inode_pages_range
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] vfs_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] blk_finish_plug
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] do_sync_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] blk_flush_plug_list
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_file_aio_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] queue_unplugged
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_file_buffered_aio_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] generic_file_buffered_write
+ 0.82% 0.00% test1 [kernel.kallsyms] [k] xfs_vm_write_begin
0.55% 0.27% test1 [kernel.kallsyms] [k] _xfs_buf_find
+ 0.55% 0.55% test1 [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_finish
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_fix_freelist
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_read_agf
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_read_agf
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_trans_read_buf_map
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] __pagevec_release
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_buf_read_map
+ 0.55% 0.00% test1 [kernel.kallsyms] [k] xfs_buf_get_map
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_perag_get
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_btree_insrec
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_extent_busy_trim
0.27% 0.27% test1 [kernel.kallsyms] [k] finish_task_switch
0.27% 0.27% test1 [mptbase] [k] mpt_put_msg_frame
0.27% 0.27% test1 [kernel.kallsyms] [k] _cond_resched
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_vm_releasepage
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_cil_prepare_item.isra.2
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_iext_bno_to_ext
0.27% 0.27% test1 [kernel.kallsyms] [k] get_page_from_freelist
0.27% 0.27% test1 [kernel.kallsyms] [k] xfs_trans_log_efi_extent
0.27% 0.00% test1 [kernel.kallsyms] [k] wait_on_page_bit
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_trans_free_extent
0.27% 0.00% test1 [kernel.kallsyms] [k] __wait_on_bit
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_free_extent
0.27% 0.00% test1 [kernel.kallsyms] [k] bit_wait_io
0.27% 0.00% test1 [kernel.kallsyms] [k] io_schedule
0.27% 0.00% test1 [kernel.kallsyms] [k] dm_make_request
0.27% 0.00% test1 [kernel.kallsyms] [k] io_schedule_timeout
0.27% 0.00% test1 [kernel.kallsyms] [k] truncate_inode_page
0.27% 0.00% test1 [kernel.kallsyms] [k] __split_and_process_bio
0.27% 0.00% test1 [kernel.kallsyms] [k] __xfs_trans_roll
0.27% 0.00% test1 [kernel.kallsyms] [k] do_invalidatepage
0.27% 0.00% test1 [kernel.kallsyms] [k] grab_cache_page_write_begin
0.27% 0.00% test1 [kernel.kallsyms] [k] schedule_timeout
0.27% 0.00% test1 [kernel.kallsyms] [k] __clone_and_map_data_bio
0.27% 0.00% test1 [kernel.kallsyms] [k] __page_cache_alloc
0.27% 0.00% test1 [kernel.kallsyms] [k] __xfs_trans_commit
0.27% 0.00% test1 [kernel.kallsyms] [k] lru_add_drain_cpu
0.27% 0.00% test1 [kernel.kallsyms] [k] schedule
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_fixup_trees
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_bunmapi
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_vm_invalidatepage
0.27% 0.00% test1 [kernel.kallsyms] [k] __schedule
0.27% 0.00% test1 [kernel.kallsyms] [k] alloc_pages_current
0.27% 0.00% test1 [kernel.kallsyms] [k] bio_alloc_bioset
0.27% 0.00% test1 [kernel.kallsyms] [k] block_invalidatepage_range
0.27% 0.00% test1 [kernel.kallsyms] [k] pagevec_lru_move_fn
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_alloc_compute_aligned
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_bmap_search_extents
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_btree_insert
0.27% 0.00% test1 [kernel.kallsyms] [k] xfs_log_commit_cil
[root@localhost ~]# perf record -e cpu-clock -g ./test2 b
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.014 MB perf.data (4 samples) ]
[root@localhost ~]# perf report
Samples: 4 of event 'cpu-clock', Event count (approx.): 1000000
Children Self Command Shared Object Symbol
+ 100.00% 0.00% test2 libc-2.17.so [.] __libc_start_main
+ 100.00% 0.00% test2 libc-2.17.so [.] __GI___libc_open
+ 100.00% 0.00% test2 [kernel.kallsyms] [k] system_call_fastpath
+ 100.00% 0.00% test2 [kernel.kallsyms] [k] sys_open
+ 100.00% 0.00% test2 [kernel.kallsyms] [k] do_sys_open
+ 50.00% 25.00% test2 [kernel.kallsyms] [k] kmem_cache_alloc
+ 50.00% 0.00% test2 [kernel.kallsyms] [k] do_filp_open
+ 50.00% 0.00% test2 [kernel.kallsyms] [k] path_openat
+ 50.00% 0.00% test2 [kernel.kallsyms] [k] get_empty_filp
+ 25.00% 25.00% test2 [kernel.kallsyms] [k] __slab_alloc
+ 25.00% 25.00% test2 [kernel.kallsyms] [k] __fd_install
+ 25.00% 25.00% test2 [kernel.kallsyms] [k] getname_flags
+ 25.00% 0.00% test2 [kernel.kallsyms] [k] fd_install
+ 25.00% 0.00% test2 [kernel.kallsyms] [k] getname
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.014 MB perf.data (4 samples) ]
[root@localhost ~]# perf report
Samples: 4 of event 'cpu-clock', Event count (approx.): 1000000
Children Self Command Shared Object Symbol
+ 100.00% 0.00% test2 libc-2.17.so [.] __libc_start_main
+ 100.00% 0.00% test2 libc-2.17.so [.] __GI___libc_open
+ 100.00% 0.00% test2 [kernel.kallsyms] [k] system_call_fastpath
+ 100.00% 0.00% test2 [kernel.kallsyms] [k] sys_open
+ 100.00% 0.00% test2 [kernel.kallsyms] [k] do_sys_open
+ 50.00% 25.00% test2 [kernel.kallsyms] [k] kmem_cache_alloc
+ 50.00% 0.00% test2 [kernel.kallsyms] [k] do_filp_open
+ 50.00% 0.00% test2 [kernel.kallsyms] [k] path_openat
+ 50.00% 0.00% test2 [kernel.kallsyms] [k] get_empty_filp
+ 25.00% 25.00% test2 [kernel.kallsyms] [k] __slab_alloc
+ 25.00% 25.00% test2 [kernel.kallsyms] [k] __fd_install
+ 25.00% 25.00% test2 [kernel.kallsyms] [k] getname_flags
+ 25.00% 0.00% test2 [kernel.kallsyms] [k] fd_install
+ 25.00% 0.00% test2 [kernel.kallsyms] [k] getname
很明显的是整个函数调用过程变的特别多,其中费时间的函数调用是从xfs_vm_writepages、xfs_itruncate_extents开始,谷歌了一下,xfs是一种高性能的日志文件系统。
对比可以发现truncate让系统多做了很多工作,其中最浪费时间的操作是mpt_put_msg_frame,占用了94.78%的时间,还没搞清楚具体,更难挖了,大牛看见可以指点指点,继续研究ing…
转载请注明:小Y » file_put_contents的一个坑