search

google-code-export / s3ql

Automatically exported from code.google.com/p/s3ql
0 stars 0 forks source link

mount.s3ql consumes ~1% CPU even when idle #259

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
mount.s3ql uses ~5% CPU usage per mount on my (test) server. Is this normal and 
what is it doing while idle? Could this be reduced somewhat?

top - 15:34:13 up 4 days,  1:42,  1 user,  load average: 1.16, 1.91, 4.09
Tasks: 118 total,   1 running, 117 sleeping,   0 stopped,   0 zombie
Cpu(s):  1.3%us, 27.2%sy,  0.0%ni, 71.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   1026592k total,   664132k used,   362460k free,    99212k buffers
Swap:  2610520k total,    13240k used,  2597280k free,   363044k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                     
 1579 root      20   0 98788 8700 1668 S  4.9  0.8 271:33.08 mount.s3ql                                                                                                  
 1588 root      20   0 99964 9736 2428 S  4.6  0.9 271:40.07 mount.s3ql                                                                                                  
 1683 root      20   0 99092 9724 2508 S  4.6  0.9 270:23.74 mount.s3ql                                                                                                  
 1609 root      20   0  163m  12m 2724 S  4.3  1.2 548:38.10 mount.s3ql                                                                                                  
 1618 root      20   0  104m 9856 2572 S  4.3  1.0 272:58.69 mount.s3ql                                                                                                  
 3045 root      20   0  113m  10m 2608 S  3.9  1.0 207:36.51 mount.s3ql                                                                                                  
11993 martin    20   0  2548 1188  904 R  1.0  0.1   0:05.12 top                

11849 martin    20   0  8492 1468  872 S  0.7  0.1   0:01.86 sshd

Original issue reported on code.google.com by mrva...@gmail.com on 13 Jun 2011 at 1:38

GoogleCodeExporter commented 9 years ago 
Does this happen with a fresh mount and empty file system as well? Please enale 
debug logging and see if that gives a clue as to what S3QL is doing.

Original comment by Nikolaus@rath.org on 13 Jun 2011 at 2:13

GoogleCodeExporter commented 9 years ago 
# mount.s3ql --homedir /var/s3ql --allow-other --debug all --fg 
s3://xxxxxxx.s3qldebug /mnt/s3ql/s3qldebug &> /tmp/s3ql-debug.log

# tail -f s3ql-debug.log 
Using backend credentials from /var/s3ql/authinfo
Using cached metadata.
Mounting filesystem...

top:
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
12925 root      20   0 82136  13m 6888 S  4.3  1.4   0:07.23 mount.s3ql

mount.log:
2011-06-13 16:19:20.936 [12925] MainThread: [common] Using backend credentials 
from /var/s3ql/authinfo
2011-06-13 16:19:20.946 [12925] MainThread: [backend.s3] Creating new boto 
connection (active conns: 0)...
2011-06-13 16:19:21.008 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:20 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:21.009 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:21.010 [12925] MainThread: [boto] Path: /?&max-keys=0
2011-06-13 16:19:21.010 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:21.011 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:20 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:3ojTnk5DlfhjPdDE6vzW4CPwIXg=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:21.011 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:21.027 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:21.615 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&max-keys=0
2011-06-13 16:19:21.618 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:21.782 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix></Prefix><Marker></Marker><MaxKeys>0</MaxKeys><IsTruncated>false</IsTruncated
></ListBucketResult>
2011-06-13 16:19:21.815 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:21 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:21.815 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:21.815 [12925] MainThread: [boto] Path: /?&max-keys=0
2011-06-13 16:19:21.815 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:21.816 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:21 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:Jvsbh5pFT5/0RSspq2GgicFAcmQ=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:21.817 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:21.818 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:22.108 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&max-keys=0
2011-06-13 16:19:22.177 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix></Prefix><Marker></Marker><MaxKeys>0</MaxKeys><IsTruncated>false</IsTruncated
></ListBucketResult>
2011-06-13 16:19:22.183 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:22 GMT
/xxxx.s3qldebug/?location
2011-06-13 16:19:22.184 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:22.185 [12925] MainThread: [boto] Path: /?location
2011-06-13 16:19:22.186 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:22.187 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:22 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:nV+M1/LfmIZzCFD6iWvYxrglp38=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:22.188 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:22.192 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:22.422 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:22 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:22.422 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:22.431 [12925] MainThread: [boto] Path: /?&max-keys=0
2011-06-13 16:19:22.453 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:22.454 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:22 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:mVvRjww+8+GuKlX/kwHIT/1KjdE=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:22.455 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:22.560 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&max-keys=0
2011-06-13 16:19:22.615 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix></Prefix><Marker></Marker><MaxKeys>0</MaxKeys><IsTruncated>false</IsTruncated
></ListBucketResult>
2011-06-13 16:19:22.618 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:22 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:22.619 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:22.620 [12925] MainThread: [boto] Path: /?&max-keys=0
2011-06-13 16:19:22.621 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:22.621 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:22 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:mVvRjww+8+GuKlX/kwHIT/1KjdE=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:22.622 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:22.623 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:22.936 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&max-keys=0
2011-06-13 16:19:22.990 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix></Prefix><Marker></Marker><MaxKeys>0</MaxKeys><IsTruncated>false</IsTruncated
></ListBucketResult>
2011-06-13 16:19:22.990 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:22 GMT
/xxxx.s3qldebug/?location
2011-06-13 16:19:22.990 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:22.990 [12925] MainThread: [boto] Path: /?location
2011-06-13 16:19:22.992 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:22.993 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:22 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:nV+M1/LfmIZzCFD6iWvYxrglp38=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:22.995 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:22.996 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:23.230 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:23 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:23.237 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:23.237 [12925] MainThread: [boto] Path: /?&max-keys=0
2011-06-13 16:19:23.238 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:23.241 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:23 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:KOS/MvINtTxXpr63QtNAOKvI/cM=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:23.242 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:23.379 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&max-keys=0
2011-06-13 16:19:23.447 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix></Prefix><Marker></Marker><MaxKeys>0</MaxKeys><IsTruncated>false</IsTruncated
></ListBucketResult>
2011-06-13 16:19:23.450 [12925] MainThread: [boto] Canonical: HEAD

Mon, 13 Jun 2011 14:19:23 GMT
/xxxx.s3qldebug/s3ql_passphrase
2011-06-13 16:19:23.451 [12925] MainThread: [boto] Method: HEAD
2011-06-13 16:19:23.451 [12925] MainThread: [boto] Path: /s3ql_passphrase
2011-06-13 16:19:23.454 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:23.454 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:23 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:MGwspZgprwBwG9frtev7jvi7ovI=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:23.455 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:23.457 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:23.676 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/s3ql_passphrase
2011-06-13 16:19:23.725 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:23 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:23.725 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:23.725 [12925] MainThread: [boto] Path: /?&max-keys=0
2011-06-13 16:19:23.725 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:23.725 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:23 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:KOS/MvINtTxXpr63QtNAOKvI/cM=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:23.728 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:23.729 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:24.054 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&max-keys=0
2011-06-13 16:19:24.170 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix></Prefix><Marker></Marker><MaxKeys>0</MaxKeys><IsTruncated>false</IsTruncated
></ListBucketResult>
2011-06-13 16:19:24.187 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:24 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:24.187 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:24.187 [12925] MainThread: [boto] Path: /?&prefix=s3ql_seq_no_
2011-06-13 16:19:24.187 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:24.187 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:24 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:vwwZBRd9GDRAndSJJRbgjpB51QU=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:24.187 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:24.187 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:24.378 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&prefix=s3ql_seq_no_
2011-06-13 16:19:24.941 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix>s3ql_seq_no_</Prefix><Marker></Marker><MaxKeys>1000</MaxKeys><IsTruncated>fal
se</IsTruncated><Contents><Key>s3ql_seq_no_0</Key><LastModified>2011-06-13T14:17
:45.000Z</LastModified><ETag>"108420939ea67b1c09b00be4a1f6473b"</ETag><Size>60</
Size><Owner><ID>5a373585e125edae5a52e83d0160937cbe50d116a7912e1a87f04eac8a3ff013
</ID><DisplayName>xxxx</DisplayName></Owner><StorageClass>STANDARD</StorageClass
></Contents><Contents><Key>s3ql_seq_no_1</Key><LastModified>2011-06-13T14:17:55.
000Z</LastModified><ETag>"108420939ea67b1c09b00be4a1f6473b"</ETag><Size>60</Size
><Owner><ID>5a373585e125edae5a52e83d0160937cbe50d116a7912e1a87f04eac8a3ff013</ID
><DisplayName>xxxx</DisplayName></Owner><StorageClass>STANDARD</StorageClass></C
ontents></ListBucketResult>
2011-06-13 16:19:24.945 [12925] MainThread: [mount] Using cached metadata.
2011-06-13 16:19:26.332 [12925] MainThread: [boto] Canonical: GET

Mon, 13 Jun 2011 14:19:26 GMT
/xxxx.s3qldebug/
2011-06-13 16:19:26.334 [12925] MainThread: [boto] Method: GET
2011-06-13 16:19:26.335 [12925] MainThread: [boto] Path: /?&max-keys=0
2011-06-13 16:19:26.336 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:26.337 [12925] MainThread: [boto] Headers: {'Date': 'Mon, 13 
Jun 2011 14:19:26 GMT', 'Content-Length': '0', 'Authorization': 'AWS 
xxxxx:8r1ecB/LeaVzX+Do0wI6zMRb47k=', 'User-Agent': 'Boto/1.9b (linux2)'}
2011-06-13 16:19:26.341 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:26.342 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:26.668 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/?&max-keys=0
2011-06-13 16:19:26.710 [12925] MainThread: [boto] <?xml version="1.0" 
encoding="UTF-8"?>
<ListBucketResult 
xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>xxxx.s3qldebug</Name><Pref
ix></Prefix><Marker></Marker><MaxKeys>0</MaxKeys><IsTruncated>false</IsTruncated
></ListBucketResult>
2011-06-13 16:19:26.759 [12925] MainThread: [boto] Canonical: PUT
EIQgk56mexwJsAvkofZHOw==
application/octet-stream
Mon, 13 Jun 2011 14:19:26 GMT
x-amz-meta-compression:LZMA
x-amz-meta-encryption:None
x-amz-meta-meta:gAJOLg==
/xxxx.s3qldebug/s3ql_seq_no_2
2011-06-13 16:19:26.760 [12925] MainThread: [boto] Method: PUT
2011-06-13 16:19:26.761 [12925] MainThread: [boto] Path: /s3ql_seq_no_2
2011-06-13 16:19:26.761 [12925] MainThread: [boto] Data: 
2011-06-13 16:19:26.762 [12925] MainThread: [boto] Headers: {'x-amz-meta-meta': 
'gAJOLg==', 'x-amz-meta-compression': 'LZMA', 'Content-Length': '60', 
'x-amz-meta-encryption': 'None', 'User-Agent': 'Boto/1.9b (linux2)', 'Expect': 
'100-Continue', 'Date': 'Mon, 13 Jun 2011 14:19:26 GMT', 'Content-MD5': 
'EIQgk56mexwJsAvkofZHOw==', 'Content-Type': 'application/octet-stream', 
'Authorization': 'AWS xxxxx:LrbnaFl0IYpNjcyJZV0Q3vyGjmU='}
2011-06-13 16:19:26.765 [12925] MainThread: [boto] Host: 
xxxx.s3qldebug.s3.amazonaws.com
2011-06-13 16:19:26.766 [12925] MainThread: [boto] establishing HTTP connection
2011-06-13 16:19:27.021 [12925] MainThread: [boto] Redirecting: 
http://xxxx.s3qldebug.s3-external-3.amazonaws.com/s3ql_seq_no_2
2011-06-13 16:19:27.163 [12925] MainThread: [BlockCache] Initializing
2011-06-13 16:19:27.166 [12925] MainThread: [mount] Mounting filesystem...
2011-06-13 16:19:27.167 [12925] MainThread: [fuse] Initializing llfuse
2011-06-13 16:19:27.173 [12925] MainThread: [fuse] Calling fuse_mount
2011-06-13 16:19:27.474 [12925] MainThread: [fuse] Calling fuse_lowlevel_new
2011-06-13 16:19:27.485 [12925] MainThread: [fuse] Calling 
fuse_set_signal_handlers
2011-06-13 16:19:27.485 [12925] MainThread: [fuse] Calling fuse_session_add_chan
2011-06-13 16:19:27.495 [12925] MainThread: [fuse] Calling fuse_session_loop_mt
2011-06-13 16:19:27.506 [12925] Metadata-Upload-Thread: [mount] 
MetadataUploadThread: start
2011-06-13 16:19:27.533 [12925] Dummy-3: [BlockCache] init: start
2011-06-13 16:19:27.549 [12925] Dummy-3: [BlockCache] init: end
2011-06-13 16:19:27.600 [12925] CommitThread: [BlockCache] CommitThread: start
2011-06-13 16:19:27.608 [12925] Inode Flush Thread: [fs] FlushThread: start

Original comment by mrva...@gmail.com on 13 Jun 2011 at 2:31

GoogleCodeExporter commented 9 years ago 
All these log messages are from the S3QL startup, not from S3QL running idle. 
Could you please attach (don't include them in the message) the logs from the 
time when the S3QL file system was not accessed at all, yet S3QL was consuming 
CPU time?

Thanks!

Original comment by Nikolaus@rath.org on 13 Jun 2011 at 4:11

GoogleCodeExporter commented 9 years ago 
There is no more. This is what s3ql does while using 5% CPU load. I've waited 
several minutes before posting the above output.

Original comment by mrva...@gmail.com on 13 Jun 2011 at 4:21

GoogleCodeExporter commented 9 years ago 
Could you install a debugging version of S3QL and provide a stack-trace and 
core dump as explained on 
http://code.google.com/p/s3ql/wiki/ProvidingDebuggingInfo?

Original comment by Nikolaus@rath.org on 13 Jun 2011 at 5:51

GoogleCodeExporter commented 9 years ago 
Here are the output of mount.log after the stacktrace command and the requested 
core dump while the mount was idle.

Original comment by mrva...@gmail.com on 14 Jun 2011 at 9:09

Attachments:

GoogleCodeExporter commented 9 years ago 
Thanks! There is nothing unusual in mount.log. For some reason I'm unable to 
get a decent backtrace out of your core file though.

Once you have attached gdb to the mount.s3ql process running under python-dbg, 
could you please run "thread apply all bt" and attach the output? Hopefully 
that will finally tell what's going on.

Original comment by Nikolaus@rath.org on 15 Jun 2011 at 8:27

GoogleCodeExporter commented 9 years ago 
I hope I made no mistakes selecting and pasting the output to my editor.

Original comment by mrva...@gmail.com on 16 Jun 2011 at 7:19

Attachments:

GoogleCodeExporter commented 9 years ago 
No, this is perfect. But I have no idea why S3QL appears to be consuming CPU 
time on your system. When you look at the backtrace, you can see that all 
threads are either sleeping (executing a select() syscall) or waiting for 
request to come in (executing a read() syscall).

So there are 3 possibilities:

1. You managed to print the backtrace at a point where S3QL was actually not 
consuming CPU time. The chances for that are rather slim.

2. The backtrace is wrong (rather unlikely, that'd be a bug in gdb, and a 
rather serious one at that).

3. The CPU consumption is misleading. This may sound unlikely as well, but at 
the moment is still the most likely explanation to me. 

So the bottom line of this is: I don't really know what to do.

Have you tried to run a really CPU intensive application once with, and once 
without S3QL running and checked if it's really 5% faster without S3QL running?

Original comment by Nikolaus@rath.org on 18 Jun 2011 at 12:25

GoogleCodeExporter commented 9 years ago 
The only thing I can think of is that python's sleep isn't as sleepy as it 
sounds. It may be ticking away ticks instead of asking the kernel to wake it up 
in due time? Maybe you're sleeping very short naps (mils?). In that case the 
CPU usage should go up a bit on older/slower HW. My s3ql mounts run in a 
(virtualbox) VM on a 4core Xeon.
Are you sure you're waiting/sleeping like you should in python (mind you, I'm 
not a python programmer, so I can't tell).

Anyway thx for checking and I'll some more tests to see if the usage does make 
a difference.

Original comment by mrva...@gmail.com on 18 Jun 2011 at 7:11

GoogleCodeExporter commented 9 years ago 
Python is definetely sleeping, you can tell that from it being only in 
select(), read() and sem_wait() syscalls. There is no way that this is 
consuming any noticeable CPU. The sleep times are in the order of seconds.

Original comment by Nikolaus@rath.org on 17 Jul 2011 at 12:48

GoogleCodeExporter commented 9 years ago 
I did a little bit of extra testing. Not to be stubborn, just because I find it 
interesting. I ran mount.s3ql in forground mode for ~40 minute and timed using 
time (meanwhile doing nothing on the mount).

real    40m9.578s
user    0m7.096s
sys     1m10.556s

s3ql.mount spends a tiny 0.3% in userland, but a significant 2,9% in system. 
Exactly what top tells me (CPU usage went down to ~3% after some guest tweaks) 
so I do believe virtualisation is playing a role here, I just don't understand 
how exactly.

Original comment by mrva...@gmail.com on 18 Jul 2011 at 10:39

GoogleCodeExporter commented 9 years ago 
1.2 reduces but does not completely resolve this issue. It's now reduced to 
~1.5% which is much better but still not negligible.

Original comment by mrva...@gmail.com on 28 Sep 2011 at 7:46

GoogleCodeExporter commented 9 years ago 
Does it become even better if you reduce the number of removal threads in 
block_cache.py? Change the 10 to a 1:

    def init(self, threads=1):
        '''Start worker threads'''

        for _ in range(threads):
            t = threading.Thread(target=self._upload_loop)
            t.start()
            self.upload_threads.append(t)

        for _ in range(10): 
            t = threading.Thread(target=self._removal_loop)
            t.daemon = True # interruption will do no permanent harm
            t.start()
            self.removal_threads.append(t)

Original comment by Nikolaus@rath.org on 28 Sep 2011 at 8:00

GoogleCodeExporter commented 9 years ago

Original comment by Nikolaus@rath.org on 3 Oct 2011 at 9:12

GoogleCodeExporter commented 9 years ago 
Yes, a (very) short test shows that the idle mounts now use 0.7% cpu. So this 
seems to be the right direction.

Original comment by mrva...@gmail.com on 4 Oct 2011 at 6:52

GoogleCodeExporter commented 9 years ago 
It's very strange now. I have 9 mountpoints, all inactive at the moment and CPU 
usage seems to be in discreet steps. Some have 0.3%, some 0.7, 1.0, 1.3 and 
1.6, alternating all the time.

Original comment by mrva...@gmail.com on 4 Oct 2011 at 6:57

GoogleCodeExporter commented 9 years ago 
I see the same behaviour now in an unmodified 1.3 installation.

Original comment by mrva...@gmail.com on 5 Oct 2011 at 6:52

GoogleCodeExporter commented 9 years ago 
Hmm. I'm afraid I don't really have an idea how to debug this further, and I'm 
also not able to reproduce this.

Original comment by Nikolaus@rath.org on 21 Nov 2011 at 2:39

GoogleCodeExporter commented 9 years ago

Original comment by Nikolaus@rath.org on 21 Nov 2011 at 2:40

GoogleCodeExporter commented 9 years ago

Original comment by Nikolaus@rath.org on 1 Mar 2012 at 3:20

GoogleCodeExporter commented 9 years ago 
mrvanes: is this still a problem?

Thanks!

Original comment by Nikolaus@rath.org on 22 Nov 2012 at 11:02

GoogleCodeExporter commented 9 years ago 
lacking further information, I'm closing this for now. Feel free to reopen if 
the problem occurs again.

Original comment by Nikolaus@rath.org on 6 Jan 2013 at 1:43

GoogleCodeExporter commented 9 years ago 
Just saw this behaviours here:
Doing nothing, top says me:
6279 root      20   0  786m  27m 2060 S  1.2  2.8  11:00.45 mount.s3ql

root@server:~# strace -f -c -p 6279
Process 6279 attached with 25 threads - interrupt to quit

-> waited about 10 sec, Ctrl+c

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.096006         224       428           select
------ ----------- ----------- --------- --------- ----------------
100.00    0.096006                   428           total

If you need other informations, I'm here

Original comment by michele....@gmail.com on 7 Jan 2013 at 1:23

GoogleCodeExporter commented 9 years ago 
Ok, thanks for reporting, I'll reopening the bug.

Original comment by Nikolaus@rath.org on 8 Jan 2013 at 1:57

GoogleCodeExporter commented 9 years ago 
Could someone who is affected by this problem please try to run the attached 
test program and report how much CPU it consumes? The program should be doing 
nothing for 60 seconds.

Original comment by Nikolaus@rath.org on 10 Mar 2013 at 9:12

GoogleCodeExporter commented 9 years ago 
This issue was closed by revision 6982f05f7051.

Original comment by Nikolaus@rath.org on 12 Mar 2013 at 3:09