file_put_contents的一个坑

最近在优化一个脚本的时候发现
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;                  
}

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;                  
}

测试结果

[root@localhost ~]# time ./test1 a

real    0m0.410s
user    0m0.001s
sys 0m0.096s
[root@localhost ~]# time ./test2 b

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
[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

查呀查呀查呀查
用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
[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

很明显的是整个函数调用过程变的特别多,其中费时间的函数调用是从xfs_vm_writepages、xfs_itruncate_extents开始,谷歌了一下,xfs是一种高性能的日志文件系统。
对比可以发现truncate让系统多做了很多工作,其中最浪费时间的操作是mpt_put_msg_frame,占用了94.78%的时间,还没搞清楚具体,更难挖了,大牛看见可以指点指点,继续研究ing…

转载请注明:小Y » file_put_contents的一个坑

赞 (0) 评论 (0) 分享 ()

评论 抢沙发

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址