Hi,
Well, of course it cannot handle that large files (I wouldn't expect that,
either). My Problem is that when I open the file, it's not just kwrite but
other processes that need so much cpu time. That kwrite is eating cpu is ok.
I cannot reproduce the behaviour for some reason however.
So for short what's now (2.6.11-mm3) hapening:
I open a file of 150MB with kwrite. Kwrite start using all cpu it can get
After some seconds pdflush kicks in. Kwrite seems to wait, and pdflush is
eating cpu cyles. These 2 alternate for some time, until file is loaded.
Please note that this happens when the file is in cache too. No Idea what
kwrite is doing here, though.
In the case described earlier ent:hda6. was eating my cpu cyles, even after
kwrite was killed!
regards
Alex
Am Donnerstag, 10. M?rz 2005 15:22 schrieb E.Gryaznova:
> I opened 190Mb textfile with kwrite and tried to do "goto line
> number 1 800 000" (file has about 6 000 000 lines). File is placed not
> on reiser4 but on ext2 partition. And I see that kwrite eats about
> 90-100% CPU.
> Does kwrite work fine for you on so big files on ext2 filesystem?
>
> I have the following kde version:
> grev@flint:~> kwrite --version
> Qt: 3.2.1
> KDE: 3.1.4
> KWrite: 4.1
>
> Thanks,
> Lena.
>
> >Begin forwarded message:
> >
> >Date: Fri, 4 Mar 2005 02:24:36 +0100
> >From: Alexander Gran <[email protected]>
> >To: [email protected]
> >Subject: 2.6.11-rc5-mm1: reiser4 eating cpu time
> >
> >
> >Hi,
> >
> >I have a reiser4 partition on a local IDE disk. I opened a 130MB textfile
> > with kwrite, and killed it while ot opened the file (took to long...)
> > diskio was finished at this point.
> >a [ent:hda6.] Process was eating 100% CPU time for several (54) seconds.
> >Is this a normal, expected behaviour?
> >After trying again, pdflush was eating much cpu time, about the same (50+
> >secs) Note that this happend after reiser4 panic (on an external disk as
> >reported several minutes ago).
> >
> >regards
> >Alex
--
Encrypted Mails welcome.
PGP-Key at http://zodiac.dnsalias.org/misc/pgpkey.asc | Key-ID: 0x6D7DD291
On Sun, 2005-03-13 at 14:24 +0100, Alexander Gran wrote:
> Hi,
>
> Well, of course it cannot handle that large files (I wouldn't expect that,
> either). My Problem is that when I open the file, it's not just kwrite but
> other processes that need so much cpu time. That kwrite is eating cpu is ok.
> I cannot reproduce the behaviour for some reason however.
> So for short what's now (2.6.11-mm3) hapening:
> I open a file of 150MB with kwrite. Kwrite start using all cpu it can get
> After some seconds pdflush kicks in. Kwrite seems to wait, and pdflush is
> eating cpu cyles. These 2 alternate for some time, until file is loaded.
That seems very much like expected behavior to me. I would expect kwrite
to start loading the file, and then having pdflush kick in to page out
parts of kwrite, so that it can allocate more memory. Then kwrite will
continue to load until more of it needs to be paged out, at which point
pdflush will engage again, and so on, until the file is loaded.
> Please note that this happens when the file is in cache too. No Idea what
> kwrite is doing here, though.
Of course, I don't know if you may have a gig or so of RAM, but I'm
having trouble believing that a 150 MB file could be kept in cache,
especially given that kwrite allocates at least as much anonymous memory
to hold it internally.
> In the case described earlier ent:hda6. was eating my cpu cyles, even after
> kwrite was killed!
Now, I can't really speak for reiser4, but it doesn't seem too
incredible that it would be flushing page usage or rebalancing some tree
or something like that. As long as it is niced down (I dunno if it
actually is, though...), that shouldn't be a problem.
HTH
Fredrik Tolf
> regards
> Alex
>
> Am Donnerstag, 10. März 2005 15:22 schrieb E.Gryaznova:
> > I opened 190Mb textfile with kwrite and tried to do "goto line
> > number 1 800 000" (file has about 6 000 000 lines). File is placed not
> > on reiser4 but on ext2 partition. And I see that kwrite eats about
> > 90-100% CPU.
> > Does kwrite work fine for you on so big files on ext2 filesystem?
> >
> > I have the following kde version:
> > grev@flint:~> kwrite --version
> > Qt: 3.2.1
> > KDE: 3.1.4
> > KWrite: 4.1
> >
> > Thanks,
> > Lena.
> >
> > >Begin forwarded message:
> > >
> > >Date: Fri, 4 Mar 2005 02:24:36 +0100
> > >From: Alexander Gran <[email protected]>
> > >To: [email protected]
> > >Subject: 2.6.11-rc5-mm1: reiser4 eating cpu time
> > >
> > >
> > >Hi,
> > >
> > >I have a reiser4 partition on a local IDE disk. I opened a 130MB textfile
> > > with kwrite, and killed it while ot opened the file (took to long...)
> > > diskio was finished at this point.
> > >a [ent:hda6.] Process was eating 100% CPU time for several (54) seconds.
> > >Is this a normal, expected behaviour?
> > >After trying again, pdflush was eating much cpu time, about the same (50+
> > >secs) Note that this happend after reiser4 panic (on an external disk as
> > >reported several minutes ago).
> > >
> > >regards
> > >Alex
>
Am Sonntag, 13. März 2005 14:44 schrieben Sie:
> That seems very much like expected behavior to me. I would expect kwrite
> to start loading the file, and then having pdflush kick in to page out
> parts of kwrite, so that it can allocate more memory. Then kwrite will
> continue to load until more of it needs to be paged out, at which point
> pdflush will engage again, and so on, until the file is loaded.
Well not quite. kwrite uses not so much ram. And I have 1Gig:
alex@t40:/files/ipt$ cat gross > /dev/null
alex@t40:/files/ipt$ free
total used free shared buffers cached
Mem: 1032592 507564 525028 0 868 336072
-/+ buffers/cache: 170624 861968
Swap: 498920 0 498920
alex@t40:/files/ipt$ kwrite gross
[1]+ Stopped kwrite gross
# kwrite loaded completely
alex@t40:/files/ipt$ free
total used free shared buffers cached
Mem: 1032592 848900 183692 0 876 651632
-/+ buffers/cache: 196392 836200
Swap: 498920 0 498920
Acording to top:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ CODE DATA COMMAND
18436 alex 16 0 44476 29m 14m S 0.0 2.9 0:11.04 4 13m kwrite
> Of course, I don't know if you may have a gig or so of RAM, but I'm
> having trouble believing that a 150 MB file could be kept in cache,
> especially given that kwrite allocates at least as much anonymous memory
> to hold it internally.
Is there any whay I can be sure a file is cached? cat file > /dev/null takes
130ms, that should be ok?
> Now, I can't really speak for reiser4, but it doesn't seem too
> incredible that it would be flushing page usage or rebalancing some tree
> or something like that. As long as it is niced down (I dunno if it
> actually is, though...), that shouldn't be a problem.
Well, It's not niced down, and it was doing what so ever while reading, not
while writing?
regards
Alex
> > regards
> > Alex
> >
> > Am Donnerstag, 10. März 2005 15:22 schrieb E.Gryaznova:
> > > I opened 190Mb textfile with kwrite and tried to do "goto line
> > > number 1 800 000" (file has about 6 000 000 lines). File is placed not
> > > on reiser4 but on ext2 partition. And I see that kwrite eats about
> > > 90-100% CPU.
> > > Does kwrite work fine for you on so big files on ext2 filesystem?
> > >
> > > I have the following kde version:
> > > grev@flint:~> kwrite --version
> > > Qt: 3.2.1
> > > KDE: 3.1.4
> > > KWrite: 4.1
> > >
> > > Thanks,
> > > Lena.
> > >
> > > >Begin forwarded message:
> > > >
> > > >Date: Fri, 4 Mar 2005 02:24:36 +0100
> > > >From: Alexander Gran <[email protected]>
> > > >To: [email protected]
> > > >Subject: 2.6.11-rc5-mm1: reiser4 eating cpu time
> > > >
> > > >
> > > >Hi,
> > > >
> > > >I have a reiser4 partition on a local IDE disk. I opened a 130MB
> > > > textfile with kwrite, and killed it while ot opened the file (took to
> > > > long...) diskio was finished at this point.
> > > >a [ent:hda6.] Process was eating 100% CPU time for several (54)
> > > > seconds. Is this a normal, expected behaviour?
> > > >After trying again, pdflush was eating much cpu time, about the same
> > > > (50+ secs) Note that this happend after reiser4 panic (on an external
> > > > disk as reported several minutes ago).
> > > >
> > > >regards
> > > >Alex
--
Encrypted Mails welcome.
PGP-Key at http://zodiac.dnsalias.org/misc/pgpkey.asc | Key-ID: 0x6D7DD291
On Sunday 13 March 2005 15:24, Alexander Gran wrote:
> Hi,
>
> Well, of course it cannot handle that large files (I wouldn't expect that,
> either). My Problem is that when I open the file, it's not just kwrite but
> other processes that need so much cpu time. That kwrite is eating cpu is ok.
> I cannot reproduce the behaviour for some reason however.
> So for short what's now (2.6.11-mm3) hapening:
> I open a file of 150MB with kwrite. Kwrite start using all cpu it can get
> After some seconds pdflush kicks in. Kwrite seems to wait, and pdflush is
> eating cpu cyles. These 2 alternate for some time, until file is loaded.
I bet kwrite does something silly.
Use strace -tt to find out whether kwrite spends that much CPU
by doing zillions of syscalls or not.
--
vda
Am Dienstag, 15. M?rz 2005 07:57 schrieb Denis Vlasenko:
> Use strace -tt to find out whether kwrite spends that much CPU
> by doing zillions of syscalls or not.
Actually pdflush always kicks in after a write call. Summary:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
62.13 2.151461 1213 1774 write
27.35 0.946942 19 49602 read
3.52 0.121736 42 2913 2 munmap
3.01 0.104310 385 271 close
0.83 0.028608 10 2901 mmap2
0.79 0.027422 6 4874 select
0.69 0.023733 2 9804 gettimeofday
0.43 0.014863 3 5615 ioctl
0.41 0.014047 9 1536 lseek
0.14 0.004890 10 505 248 open
0.11 0.003968 6 627 60 stat64
0.10 0.003302 6 574 223 access
0.09 0.002997 749 4 fdatasync
0.07 0.002380 9 280 26 lstat64
0.06 0.002049 89 23 writev
0.06 0.002026 8 245 brk
0.04 0.001479 4 388 fstat64
0.04 0.001234 8 147 old_mmap
0.03 0.001119 224 5 rename
0.03 0.000889 64 14 1 unlink
0.02 0.000591 591 1 shutdown
0.01 0.000515 32 16 getdents64
0.01 0.000503 101 5 2 connect
0.01 0.000293 59 5 link
0.01 0.000185 3 72 fcntl64
0.00 0.000170 28 6 socket
0.00 0.000140 2 65 rt_sigaction
0.00 0.000128 7 18 fchmod
0.00 0.000116 9 13 readv
0.00 0.000110 3 32 1 _llseek
0.00 0.000080 16 5 readlink
0.00 0.000071 3 23 uname
0.00 0.000068 7 10 fchown32
0.00 0.000061 2 26 getuid32
0.00 0.000055 2 29 rt_sigprocmask
0.00 0.000049 2 20 umask
0.00 0.000045 23 2 1 bind
0.00 0.000038 13 3 chdir
0.00 0.000037 2 15 getgid32
0.00 0.000036 5 7 getcwd
0.00 0.000033 2 15 getpid
0.00 0.000023 8 3 pipe
0.00 0.000014 4 4 futex
0.00 0.000012 12 1 accept
0.00 0.000006 2 4 time
0.00 0.000006 6 1 set_thread_area
0.00 0.000005 2 3 geteuid32
0.00 0.000004 2 2 getrlimit
0.00 0.000003 3 1 getsockname
0.00 0.000003 3 1 getsockopt
0.00 0.000002 2 1 set_tid_address
0.00 0.000002 2 1 listen
0.00 0.000002 2 1 1 setsockopt
0.00 0.000001 1 1 getegid32
------ ----------- ----------- --------- --------- ----------------
100.00 3.462862 82514 565 total
UOUO. Strange again.
THe above was on ext3. I then copied the file to reiser4. Copy command exited
quite fast, however pdflush was again taking ~20s CPU time....
Here are some strange benchmarks on reiser4:
alex@t40:/files/ipt$ cp gross /tmp/
alex@t40:/files/ipt$ cd /tmp/
alex@t40:/tmp$ strace -ttc kwrite gross
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
75.90 4.121664 2266 1819 write
17.45 0.947628 67 14152 read
2.09 0.113706 39 2911 2 munmap
2.01 0.109136 406 269 close
0.52 0.028380 10 2899 mmap2
0.46 0.025053 5 4903 select
0.45 0.024209 2 9885 gettimeofday
0.25 0.013516 9 1536 lseek
0.24 0.013252 2 5739 ioctl
0.12 0.006303 13 503 248 open
0.11 0.005991 1498 4 fdatasync
0.07 0.003825 6 627 60 stat64
0.05 0.002853 5 572 223 access
0.04 0.002419 105 23 writev
0.03 0.001408 282 5 rename
0.03 0.001374 5 279 26 lstat64
0.02 0.001291 92 14 1 unlink
0.02 0.001130 3 384 fstat64
0.02 0.000939 6 147 old_mmap
0.02 0.000926 926 1 shutdown
0.02 0.000855 4 241 brk
0.01 0.000690 38 18 fchmod
0.01 0.000503 72 7 getcwd
0.01 0.000488 31 16 getdents64
0.01 0.000456 91 5 link
0.01 0.000440 88 5 2 connect
0.01 0.000312 31 10 fchown32
0.00 0.000254 254 1 set_thread_area
0.00 0.000188 3 72 fcntl64
0.00 0.000181 3 65 rt_sigaction
0.00 0.000111 9 13 readv
0.00 0.000091 18 5 readlink
0.00 0.000086 3 30 1 _llseek
0.00 0.000086 14 6 socket
0.00 0.000072 3 23 uname
0.00 0.000070 4 20 umask
0.00 0.000067 3 26 getuid32
0.00 0.000050 25 2 1 bind
0.00 0.000044 2 29 rt_sigprocmask
0.00 0.000039 3 15 getgid32
0.00 0.000030 10 3 chdir
0.00 0.000030 2 15 getpid
0.00 0.000026 9 3 pipe
0.00 0.000017 4 4 futex
0.00 0.000013 13 1 accept
0.00 0.000007 2 4 time
0.00 0.000005 2 3 geteuid32
0.00 0.000004 2 2 getrlimit
0.00 0.000003 3 1 listen
0.00 0.000003 3 1 getsockname
0.00 0.000003 3 1 1 setsockopt
0.00 0.000003 3 1 getsockopt
0.00 0.000002 2 1 getegid32
0.00 0.000002 2 1 set_tid_address
------ ----------- ----------- --------- --------- ----------------
100.00 5.430234 47322 565 total
alex@t40:/tmp$ strace -c kwrite gross
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
42.91 0.939626 69 13614 1 read
40.34 0.883494 496 1782 write
5.35 0.117072 434 270 close
5.31 0.116266 40 2912 2 munmap
1.37 0.029961 10 2900 mmap2
1.20 0.026276 5 4863 select
0.89 0.019557 2 9786 gettimeofday
0.65 0.014222 9 1536 lseek
0.59 0.012985 2 5541 ioctl
0.29 0.006266 12 504 248 open
0.15 0.003193 5 627 60 stat64
0.14 0.003121 5 573 223 access
0.14 0.002994 749 4 fdatasync
0.09 0.002078 94 22 writev
0.09 0.002067 413 5 rename
0.08 0.001780 127 14 1 unlink
0.06 0.001306 9 147 old_mmap
0.06 0.001274 5 279 26 lstat64
0.05 0.001178 3 386 fstat64
0.04 0.000983 4 245 brk
0.03 0.000731 46 16 getdents64
0.03 0.000591 591 1 shutdown
0.02 0.000539 30 18 fchmod
0.02 0.000487 97 5 2 connect
0.02 0.000371 74 5 link
0.01 0.000258 26 10 fchown32
0.01 0.000212 3 65 rt_sigaction
0.01 0.000179 2 72 fcntl64
0.01 0.000115 9 13 readv
0.00 0.000109 4 31 1 _llseek
0.00 0.000089 18 5 readlink
0.00 0.000087 15 6 socket
0.00 0.000070 3 23 uname
0.00 0.000049 2 29 rt_sigprocmask
0.00 0.000044 22 2 1 bind
0.00 0.000042 2 26 getuid32
0.00 0.000038 3 15 getgid32
0.00 0.000036 2 20 umask
0.00 0.000028 2 15 getpid
0.00 0.000022 7 3 pipe
0.00 0.000022 3 7 getcwd
0.00 0.000015 4 4 futex
0.00 0.000011 11 1 accept
0.00 0.000009 3 3 chdir
0.00 0.000008 2 4 time
0.00 0.000005 2 3 geteuid32
0.00 0.000005 5 1 set_thread_area
0.00 0.000003 2 2 getrlimit
0.00 0.000003 3 1 getsockname
0.00 0.000003 3 1 getsockopt
0.00 0.000002 2 1 getegid32
0.00 0.000002 2 1 set_tid_address
0.00 0.000002 2 1 listen
0.00 0.000002 2 1 1 setsockopt
------ ----------- ----------- --------- --------- ----------------
100.00 2.189888 46421 566 total
alex@t40:/tmp$ strace -c kwrite gross
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
42.39 0.953074 70 13601 1 read
41.55 0.934274 521 1792 write
5.19 0.116578 433 269 close
5.02 0.112941 39 2911 2 munmap
1.33 0.030014 10 2899 mmap2
1.18 0.026478 5 4857 select
0.93 0.020984 2 9777 gettimeofday
0.54 0.012233 2 5506 ioctl
0.50 0.011281 7 1536 lseek
0.22 0.004967 10 503 248 open
0.14 0.003115 5 572 223 access
0.14 0.003112 5 627 60 stat64
0.13 0.002998 750 4 fdatasync
0.11 0.002375 16 147 old_mmap
0.09 0.002057 89 23 writev
0.07 0.001488 298 5 rename
0.06 0.001449 5 279 26 lstat64
0.06 0.001253 251 5 2 connect
0.05 0.001208 3 384 fstat64
0.05 0.001091 78 14 1 unlink
0.04 0.000905 4 245 brk
0.03 0.000708 39 18 fchmod
0.03 0.000696 696 1 shutdown
0.02 0.000532 76 7 getcwd
0.02 0.000506 32 16 getdents64
0.02 0.000428 86 5 link
0.01 0.000335 34 10 fchown32
0.01 0.000189 3 72 fcntl64
0.01 0.000165 3 65 rt_sigaction
0.00 0.000112 9 13 readv
0.00 0.000090 15 6 socket
0.00 0.000089 18 5 readlink
0.00 0.000087 3 30 1 _llseek
0.00 0.000074 3 23 uname
0.00 0.000068 3 26 getuid32
0.00 0.000057 3 20 umask
0.00 0.000049 2 29 rt_sigprocmask
0.00 0.000044 3 15 getgid32
0.00 0.000042 21 2 1 bind
0.00 0.000033 11 3 chdir
0.00 0.000029 2 15 getpid
0.00 0.000024 8 3 pipe
0.00 0.000014 4 4 futex
0.00 0.000013 13 1 accept
0.00 0.000007 2 4 time
0.00 0.000006 2 3 geteuid32
0.00 0.000006 6 1 set_thread_area
0.00 0.000004 2 2 getrlimit
0.00 0.000003 3 1 getsockname
0.00 0.000003 3 1 1 setsockopt
0.00 0.000003 3 1 getsockopt
0.00 0.000002 2 1 set_tid_address
0.00 0.000002 2 1 listen
0.00 0.000001 1 1 getegid32
------ ----------- ----------- --------- --------- ----------------
100.00 2.248296 46361 566 total
alex@t40:/tmp$ sync
alex@t40:/tmp$ strace -c kwrite gross
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
60.87 2.009600 1095 1836 write
28.08 0.927199 68 13630 read
3.44 0.113742 423 269 close
3.41 0.112701 39 2911 2 munmap
0.97 0.031980 6 4926 select
0.94 0.030976 11 2899 mmap2
0.71 0.023333 2 9933 gettimeofday
0.39 0.012816 8 1536 lseek
0.36 0.011994 2 5622 ioctl
0.15 0.004794 10 503 248 open
0.11 0.003540 6 627 60 stat64
0.10 0.003406 6 572 223 access
0.07 0.002398 6 384 fstat64
0.07 0.002280 99 23 writev
0.04 0.001317 263 5 rename
0.04 0.001294 5 279 26 lstat64
0.03 0.001076 77 14 1 unlink
0.03 0.001067 7 147 old_mmap
0.03 0.001001 250 4 fdatasync
0.02 0.000794 3 241 brk
0.02 0.000778 43 18 fchmod
0.02 0.000618 618 1 shutdown
0.02 0.000511 32 16 getdents64
0.01 0.000470 94 5 link
0.01 0.000442 88 5 2 connect
0.01 0.000363 36 10 fchown32
0.01 0.000192 3 72 fcntl64
0.00 0.000113 2 65 rt_sigaction
0.00 0.000104 8 13 readv
0.00 0.000087 15 6 socket
0.00 0.000085 17 5 readlink
0.00 0.000080 3 30 1 _llseek
0.00 0.000071 3 23 uname
0.00 0.000061 2 26 getuid32
0.00 0.000055 3 20 umask
0.00 0.000049 7 7 getcwd
0.00 0.000042 3 15 getgid32
0.00 0.000041 1 29 rt_sigprocmask
0.00 0.000041 21 2 1 bind
0.00 0.000031 10 3 chdir
0.00 0.000028 2 15 getpid
0.00 0.000022 7 3 pipe
0.00 0.000015 15 1 accept
0.00 0.000014 4 4 futex
0.00 0.000008 8 1 set_thread_area
0.00 0.000007 2 4 time
0.00 0.000003 2 2 getrlimit
0.00 0.000003 1 3 geteuid32
0.00 0.000003 3 1 getsockname
0.00 0.000003 3 1 getsockopt
0.00 0.000002 2 1 set_tid_address
0.00 0.000002 2 1 listen
0.00 0.000002 2 1 1 setsockopt
0.00 0.000001 1 1 getegid32
------ ----------- ----------- --------- --------- ----------------
100.00 3.301655 46771 565 total
--
Encrypted Mails welcome.
PGP-Key at http://zodiac.dnsalias.org/misc/pgpkey.asc | Key-ID: 0x6D7DD291