Re: Extremely slooooow __sys_ftruncate?

On Thu, 20 Mar 2008, Steve Kargl wrote:

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

Thanks for the test code.  truncate is only handled by softupdates when 
it's a truncate to 0.  Otherwise it's synchronous. :/

I would argue that the program is doing something terrible.  However, we 
also shouldn't be so slow.

I'm confused by your example however.  For each iteration we're writing 4 
bytes and then truncating 3 of them off?  Is that right?  Is that what the 
compiler is actually doing?

Thanks,
Jeff

>
> 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
> _______________________________________________
> freebsd-current_at_freebsd.org mailing list
> http://lists.freebsd.org/mailman/listinfo/freebsd-current
> To unsubscribe, send any mail to "freebsd-current-unsubscribe_at_freebsd.org"
>