runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand285.cudf.s-e-l.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l/rand285.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand285.cudf.s-e-l.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.00 1.03 1.00 5/36 8172
/proc/meminfo: memFree=541144/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2588 CPUtime=0
/proc/8171/stat : 8171 (aspcud-trendy-1) R 8170 8171 1511 34817 1511 4202496 366 0 0 0 0 0 0 0 25 0 1 0 2018938 2650112 280 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/8171/statm: 647 280 234 194 0 34 0
[pid=8172] ppid=8171 vsize=2588 CPUtime=0
/proc/8172/stat : 8172 (aspcud-trendy-1) R 8171 8171 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2018938 2650112 46 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/8172/statm: 647 46 0 194 0 34 0

[startup+0.105409 s]
/proc/loadavg: 1.00 1.03 1.00 5/36 8172
/proc/meminfo: memFree=541144/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=0.01
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 622 2231 0 0 0 0 1 0 25 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.205452 s]
/proc/loadavg: 1.00 1.03 1.00 5/36 8172
/proc/meminfo: memFree=541144/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=0.01
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 622 2231 0 0 0 0 1 0 25 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.305465 s]
/proc/loadavg: 1.00 1.03 1.00 5/36 8172
/proc/meminfo: memFree=541144/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=0.01
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 622 2231 0 0 0 0 1 0 25 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.705577 s]
/proc/loadavg: 1.00 1.03 1.00 5/36 8172
/proc/meminfo: memFree=541144/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=0.01
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 622 2231 0 0 0 0 1 0 25 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50576 s]
/proc/loadavg: 1.00 1.03 1.00 2/39 8185
/proc/meminfo: memFree=510836/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=0.01
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 622 2231 0 0 0 0 1 0 25 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=6240 CPUtime=0.04
/proc/8183/stat : 8183 (clasp) S 8171 8171 1511 34817 1511 4202496 1472 0 0 0 3 1 0 0 18 0 1 0 2018939 6389760 1257 1283457024 134512640 136285277 4291180112 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/8183/statm: 1560 1257 177 433 0 1125 0
[pid=8184] ppid=8171 vsize=9024 CPUtime=0.18
/proc/8184/stat : 8184 (gringo) R 8171 8171 1511 34817 1511 4202496 2383 0 0 0 18 0 0 0 18 0 1 0 2018939 9240576 1571 1283457024 134512640 136933539 4291581728 18446744073709551615 135997923 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8184/statm: 2256 1571 242 592 0 1661 0
[pid=8185] ppid=8171 vsize=30576 CPUtime=1.26
/proc/8185/stat : 8185 (cudf2lp) R 8171 8171 1511 34817 1511 4202496 10056 0 0 0 121 5 0 0 25 0 1 0 2018939 31309824 7426 1283457024 134512640 135786343 4291680096 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8185/statm: 7644 7426 137 311 0 7331 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 48436

[startup+3.10619 s]
/proc/loadavg: 1.00 1.03 1.00 3/38 8185
/proc/meminfo: memFree=502668/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=36132 CPUtime=0.51
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 10499 0 0 0 46 5 0 0 18 0 1 0 2018939 36999168 8749 1283457024 134512640 136285277 4291180112 18446744073709551615 134902056 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 9033 8749 217 433 0 8598 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 38728

[startup+6.30713 s]
/proc/loadavg: 1.00 1.03 1.00 2/37 8186
/proc/meminfo: memFree=506776/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=39300 CPUtime=3.7
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 11457 0 0 0 365 5 0 0 25 0 1 0 2018939 40243200 9585 1283457024 134512640 136285277 4291180112 18446744073709551615 134734258 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 9825 9585 234 433 0 9390 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 41896

[startup+12.7087 s]
/proc/loadavg: 1.00 1.03 1.00 2/37 8186
/proc/meminfo: memFree=492160/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=50652 CPUtime=10.1
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 14311 0 0 0 1005 5 0 0 25 0 1 0 2018939 51867648 12439 1283457024 134512640 136285277 4291180112 18446744073709551615 134733691 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 12663 12439 234 433 0 12228 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 53248

[startup+25.5115 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 8187
/proc/meminfo: memFree=467500/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=75488 CPUtime=22.88
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 20494 0 0 0 2282 6 0 0 25 0 1 0 2018939 77299712 18622 1283457024 134512640 136285277 4291180112 18446744073709551615 134959557 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 18872 18622 234 433 0 18437 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 78084

[startup+51.1059 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 8187
/proc/meminfo: memFree=400912/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=141988 CPUtime=48.47
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 37115 0 0 0 4835 12 0 0 25 0 1 0 2018939 145395712 35243 1283457024 134512640 136285277 4291180112 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 35497 35243 234 433 0 35062 0
Current children cumulated CPU time (s) 51.05
Current children cumulated vsize (KiB) 144584

[startup+102.309 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 8187
/proc/meminfo: memFree=322428/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=220508 CPUtime=99.63
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 56721 0 0 0 9942 21 0 0 25 0 1 0 2018939 225800192 54849 1283457024 134512640 136285277 4291180112 18446744073709551615 134669408 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 55127 54849 234 433 0 54692 0
Current children cumulated CPU time (s) 102.21
Current children cumulated vsize (KiB) 223104

[startup+162.306 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 8187
/proc/meminfo: memFree=255964/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=286932 CPUtime=159.57
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 73284 0 0 0 15927 30 0 0 25 0 1 0 2018939 293818368 71412 1283457024 134512640 136285277 4291180112 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 71733 71412 234 433 0 71298 0
Current children cumulated CPU time (s) 162.15
Current children cumulated vsize (KiB) 289528

[startup+222.312 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 8187
/proc/meminfo: memFree=255344/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=287460 CPUtime=219.51
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 73443 0 0 0 21920 31 0 0 25 0 1 0 2018939 294359040 71571 1283457024 134512640 136285277 4291180112 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 71865 71571 234 433 0 71430 0
Current children cumulated CPU time (s) 222.09
Current children cumulated vsize (KiB) 290056

Solver just ended. Dumping a history of the last processes samples

[startup+224.013 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 8187
/proc/meminfo: memFree=255344/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=287460 CPUtime=221.21
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 73443 0 0 0 22090 31 0 0 25 0 1 0 2018939 294359040 71571 1283457024 134512640 136285277 4291180112 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 71865 71571 234 433 0 71430 0
Current children cumulated CPU time (s) 223.79
Current children cumulated vsize (KiB) 290056

[startup+224.813 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 8187
/proc/meminfo: memFree=255344/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=287460 CPUtime=222.01
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 73443 0 0 0 22170 31 0 0 25 0 1 0 2018939 294359040 71571 1283457024 134512640 136285277 4291180112 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 71865 71571 234 433 0 71430 0
Current children cumulated CPU time (s) 224.59
Current children cumulated vsize (KiB) 290056

[startup+225.613 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 8187
/proc/meminfo: memFree=255344/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=287460 CPUtime=222.81
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 73443 0 0 0 22250 31 0 0 25 0 1 0 2018939 294359040 71571 1283457024 134512640 136285277 4291180112 18446744073709551615 134948738 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 71865 71571 234 433 0 71430 0
Current children cumulated CPU time (s) 225.39
Current children cumulated vsize (KiB) 290056

[startup+226.014 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 8187
/proc/meminfo: memFree=255344/1048576 swapFree=0/0
[pid=8171] ppid=8170 vsize=2596 CPUtime=2.58
/proc/8171/stat : 8171 (aspcud-trendy-1) S 8170 8171 1511 34817 1511 4202496 623 25407 0 0 0 0 250 8 18 0 1 0 2018938 2658304 299 1283457024 134512640 135304128 4287644464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8171/statm: 649 299 251 194 0 36 0
[pid=8183] ppid=8171 vsize=148728 CPUtime=223.21
/proc/8183/stat : 8183 (clasp) R 8171 8171 1511 34817 1511 4202496 73450 0 0 0 22286 35 0 0 25 0 1 0 2018939 152297472 33851 1283457024 134512640 136285277 4291180112 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8183/statm: 37182 33851 241 433 0 36747 0
Current children cumulated CPU time (s) 225.79
Current children cumulated vsize (KiB) 151324

Child status: 0
Real time (s): 226.074
CPU time (s): 225.858
CPU user time (s): 225.39
CPU system time (s): 0.468029
CPU usage (%): 99.9044
Max. virtual memory (cumulated for all children) (KiB): 290056

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 225.39
system time used= 0.468029
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 103137
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1256
involuntary context switches= 3567

runsolver used 0 second user time and 0 second system time

The end