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: runsolver -s SIGUSR1 -M 1124 -C 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/install/rand96.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand96.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/install/rand96.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 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: 0.85 0.83 0.52 2/65 3181
/proc/meminfo: memFree=452972/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9188 CPUtime=0
/proc/3181/stat : 3181 (aspcud-basic) R 3180 3181 1745 0 -1 4202496 410 0 0 0 0 0 0 0 20 0 1 0 115185018 9408512 318 18446744073709551615 4194304 5129932 140736916854448 140736916852344 4911939 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2297 318 263 229 0 57 0

[startup+0.118433 s]
/proc/loadavg: 0.85 0.83 0.52 2/65 3181
/proc/meminfo: memFree=452972/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=0.06
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 737 3614 0 0 1 0 3 2 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200339 s]
/proc/loadavg: 0.85 0.83 0.52 2/65 3181
/proc/meminfo: memFree=452972/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=0.06
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 737 3614 0 0 1 0 3 2 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300309 s]
/proc/loadavg: 0.85 0.83 0.52 2/65 3181
/proc/meminfo: memFree=452972/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=0.06
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 737 3614 0 0 1 0 3 2 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700236 s]
/proc/loadavg: 0.85 0.83 0.52 2/65 3181
/proc/meminfo: memFree=452972/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=0.06
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 737 3614 0 0 1 0 3 2 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.86 0.83 0.52 2/67 3197
/proc/meminfo: memFree=419220/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=0.06
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 737 3614 0 0 1 0 3 2 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3197] ppid=3181 vsize=33064 CPUtime=1.41
/proc/3197/stat : 3197 (cudf2lp) R 3181 3181 1745 0 -1 4202496 9674 0 0 0 136 5 0 0 20 0 1 0 115185022 33857536 7940 18446744073709551615 4194304 5690517 140734907598112 140734907595480 4293722 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/3197/statm: 8266 7940 160 366 0 7897 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 42276

[startup+3.10032 s]
/proc/loadavg: 0.86 0.83 0.52 2/67 3197
/proc/meminfo: memFree=387352/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=0.06
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 737 3614 0 0 1 0 3 2 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3197] ppid=3181 vsize=93028 CPUtime=2.99
/proc/3197/stat : 3197 (cudf2lp) R 3181 3181 1745 0 -1 4202496 26485 0 0 0 286 13 0 0 20 0 1 0 115185022 95260672 19757 18446744073709551615 4194304 5690517 140734907598112 140734907595752 4457312 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/3197/statm: 23257 19757 160 366 0 22888 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 102240

[startup+6.30032 s]
/proc/loadavg: 0.86 0.83 0.52 2/67 3198
/proc/meminfo: memFree=396156/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=5
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 763 42934 0 0 1 0 466 33 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3198] ppid=3181 vsize=41084 CPUtime=1.21
/proc/3198/stat : 3198 (gringo) R 3181 3181 1745 0 -1 4202496 9674 0 0 0 113 8 0 0 20 0 1 0 115185525 42070016 7565 18446744073709551615 4194304 6531320 140737351532528 140737351528536 5563180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3198/statm: 10271 7565 259 571 0 9692 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 50296

[startup+12.7003 s]
/proc/loadavg: 0.88 0.84 0.53 2/67 3198
/proc/meminfo: memFree=9648/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=5
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 763 42934 0 0 1 0 466 33 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916853104 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3198] ppid=3181 vsize=408488 CPUtime=7.54
/proc/3198/stat : 3198 (gringo) R 3181 3181 1745 0 -1 4202496 106099 0 0 0 702 52 0 0 20 0 1 0 115185525 418291712 89031 18446744073709551615 4194304 6531320 140737351532528 140737351530216 5506480 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3198/statm: 102122 89031 284 571 0 101543 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 417700

[startup+25.5004 s]
/proc/loadavg: 0.90 0.84 0.53 2/68 3200
/proc/meminfo: memFree=257640/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=12.69
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 804 149037 0 0 1 0 1170 98 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916852512 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3199] ppid=3181 vsize=138072 CPUtime=12.5
/proc/3199/stat : 3199 (clasp) R 3181 3181 1745 0 -1 4202496 40326 0 0 0 1236 14 0 0 20 0 1 0 115186302 141385728 34167 18446744073709551615 4194304 6238623 140735548783696 140735548780720 4421910 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3199/statm: 34518 34167 264 500 0 34015 0
[pid=3200] ppid=3181 vsize=22040 CPUtime=0.02
/proc/3200/stat : 3200 (parse.py) S 3181 3181 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115186302 22568960 1128 18446744073709551615 4194304 6642060 140736727162016 140736727160376 140385576970016 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3200/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.21
Current children cumulated vsize (KiB) 169324

[startup+51.1004 s]
/proc/loadavg: 0.93 0.85 0.54 2/68 3200
/proc/meminfo: memFree=257640/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=12.69
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 804 149037 0 0 1 0 1170 98 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916852512 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3199] ppid=3181 vsize=138072 CPUtime=37.83
/proc/3199/stat : 3199 (clasp) R 3181 3181 1745 0 -1 4202496 40326 0 0 0 3769 14 0 0 20 0 1 0 115186302 141385728 34167 18446744073709551615 4194304 6238623 140735548783696 140735548780720 4306640 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3199/statm: 34518 34167 264 500 0 34015 0
[pid=3200] ppid=3181 vsize=22040 CPUtime=0.02
/proc/3200/stat : 3200 (parse.py) S 3181 3181 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115186302 22568960 1128 18446744073709551615 4194304 6642060 140736727162016 140736727160376 140385576970016 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3200/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.54
Current children cumulated vsize (KiB) 169324

[startup+102.3 s]
/proc/loadavg: 0.97 0.87 0.57 2/68 3200
/proc/meminfo: memFree=253176/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=12.69
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 804 149037 0 0 1 0 1170 98 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916852512 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3199] ppid=3181 vsize=142296 CPUtime=88.52
/proc/3199/stat : 3199 (clasp) R 3181 3181 1745 0 -1 4202496 41406 0 0 0 8838 14 0 0 20 0 1 0 115186302 145711104 35247 18446744073709551615 4194304 6238623 140735548783696 140735548780248 4687936 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3199/statm: 35574 35247 264 500 0 35071 0
[pid=3200] ppid=3181 vsize=22040 CPUtime=0.02
/proc/3200/stat : 3200 (parse.py) S 3181 3181 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115186302 22568960 1128 18446744073709551615 4194304 6642060 140736727162016 140736727160376 140385576970016 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3200/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.23
Current children cumulated vsize (KiB) 173548



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.6 s]
/proc/loadavg: 0.99 0.89 0.58 2/68 3200
/proc/meminfo: memFree=216596/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=12.69
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 804 149037 0 0 1 0 1170 98 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916852512 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3199] ppid=3181 vsize=178804 CPUtime=137.34
/proc/3199/stat : 3199 (clasp) R 3181 3181 1745 0 -1 4202496 50546 0 0 0 13714 20 0 0 20 0 1 0 115186302 183095296 44387 18446744073709551615 4194304 6238623 140735548783696 140735548780248 4684906 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3199/statm: 44701 44387 264 500 0 44198 0
[pid=3200] ppid=3181 vsize=22040 CPUtime=0.02
/proc/3200/stat : 3200 (parse.py) S 3181 3181 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115186302 22568960 1128 18446744073709551615 4194304 6642060 140736727162016 140736727160376 140385576970016 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3200/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 210056

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+151.6 s]
/proc/loadavg: 0.99 0.89 0.58 2/68 3200
/proc/meminfo: memFree=216596/1022884 swapFree=0/0
[pid=3181] ppid=3180 vsize=9212 CPUtime=12.69
/proc/3181/stat : 3181 (aspcud-basic) S 3180 3181 1745 0 -1 4202496 804 149037 0 0 1 0 1170 98 20 0 1 0 115185018 9433088 364 18446744073709551615 4194304 5129932 140736916854448 140736916852512 140064470004830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3181/statm: 2303 364 303 229 0 63 0
[pid=3199] ppid=3181 vsize=178804 CPUtime=137.34
/proc/3199/stat : 3199 (clasp) R 3181 3181 1745 0 -1 4202496 50546 0 0 0 13714 20 0 0 20 0 1 0 115186302 183095296 44387 18446744073709551615 4194304 6238623 140735548783696 140735548780248 4684906 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3199/statm: 44701 44387 264 500 0 44198 0
[pid=3200] ppid=3181 vsize=22040 CPUtime=0.02
/proc/3200/stat : 3200 (parse.py) S 3181 3181 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115186302 22568960 1128 18446744073709551615 4194304 6642060 140736727162016 140736727160376 140385576970016 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3200/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 210056

Child status: 0
Real time (s): 151.63
CPU time (s): 150.101
CPU user time (s): 148.881
CPU system time (s): 1.22008
CPU usage (%): 98.9917
Max. virtual memory (cumulated for all children) (KiB): 454572

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.881
system time used= 1.22008
maximum resident set size= 387276
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 202024
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 50008
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 87
involuntary context switches= 17202

runsolver used 0.388024 second user time and 0.788049 second system time

The end