Re: Extremely slooooow __sys_ftruncate?

From: Steve Kargl <sgk_at_troutmask.apl.washington.edu>
Date: Thu, 20 Mar 2008 20:45:16 -0700
On Thu, Mar 20, 2008 at 08:02:54PM -0700, Steve Kargl wrote:
> In the process of helping to debug a problem with gcc-4.4.0
> (actually a gfortran problem), I run gprof on the executable.
> The profile shows that __sys_ftruncate is extremely slow.
> 
>   %   cumulative   self              self     total           
>  time   seconds   seconds    calls  ms/call  ms/call  name    
>  85.6       6.05     6.05    51830     0.12     0.12  __sys_ftruncate [2]
>   5.6       6.44     0.40        0  100.00%           .mcount (101)
>   1.7       6.56     0.12    51872     0.00     0.00  _lseek [5]
>   1.6       6.67     0.11    52055     0.00     0.00  sigprocmask [6]
>   0.8       6.73     0.06   103687     0.00     0.00  memset [14]
>   0.4       6.76     0.03      488     0.06     0.06  __sys_write [18]
>   0.4       6.79     0.03        0  100.00%           formatted_transfer_scalar 
> 
> time ./z
>      184.21 real         0.98 user         6.57 sys
> 
> This program should finish well under 184 seconds.  The same program
> and exact same gcc/gfortran source on linux shows 
>  real    0m0.555s    user    0m0.103s    sys     0m0.452s 
> 
> Is __sys_ftruncate known to have performance problems?
> 

Well, I tried to kludge together a C example based on the
the Fortran test code and gfortran runtime library.

cc -o z -O -pg -static a.c
time ./z
      239.96 real         0.08 user         8.12 sys


  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 81.4       6.58     6.58    51830     0.13     0.13  _ftruncate [3]
 17.1       7.96     1.38    52056     0.03     0.03  _write [4]
  0.7       8.01     0.05        0  100.00%           .mcount (46)
  0.6       8.05     0.05    51830     0.00     0.00  __sys_lseek [5]
  0.1       8.06     0.01        1     7.51     7.51  fstat [9]
  0.1       8.07     0.01        1     7.51  8027.03  main [1]
  0.1       8.07     0.00    51830     0.00     0.00  lseek [13]

Hmmm, ftruncate() mapped to _ftruncate :-/

Here's the program 

#include <sys/stat.h>
#include <stdio.h>
#include <unistd.h>
#include <fcntl.h>


int
main(void) {

	int fd, off, i, j;

     	fd = open("junk", O_RDWR | O_CREAT, S_IRUSR | S_IWUSR);
	off = 0;
	for (i = 0; i < 5183; i++) {
		if (i%23 == 0) printf("i = %d\n", i);
		for (j = 0; j < 10; j++) {
     			write(fd, &off, sizeof(off));
			off++;
			lseek(fd, off, SEEK_SET);
			ftruncate(fd, off);
		}
	}
	return 0;
}

-- 
Steve
Received on Fri Mar 21 2008 - 02:46:15 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:29 UTC