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/aspuncud-basic-1.7/paranoid-size/install/rand943.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand943.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/install/rand943.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: 1.00 1.00 0.91 2/60 21417
/proc/meminfo: memFree=433320/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9204 CPUtime=0
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 115368158 9424896 332 18446744073709551615 4194304 5129932 140735398050256 140735398047720 139640726152992 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2301 332 272 229 0 61 0

[startup+0.136508 s]
/proc/loadavg: 1.00 1.00 0.91 2/60 21417
/proc/meminfo: memFree=433320/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=0.02
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 699 2807 0 0 0 0 2 0 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048912 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200288 s]
/proc/loadavg: 1.00 1.00 0.91 2/60 21417
/proc/meminfo: memFree=433320/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=0.02
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 699 2807 0 0 0 0 2 0 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048912 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300261 s]
/proc/loadavg: 1.00 1.00 0.91 2/60 21417
/proc/meminfo: memFree=433320/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=0.02
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 699 2807 0 0 0 0 2 0 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048912 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.7002 s]
/proc/loadavg: 1.00 1.00 0.91 2/60 21417
/proc/meminfo: memFree=433320/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=0.02
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 699 2807 0 0 0 0 2 0 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048912 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 1.00 1.00 0.91 2/62 21430
/proc/meminfo: memFree=376628/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=0.02
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 699 2807 0 0 0 0 2 0 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048912 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21430] ppid=21417 vsize=50676 CPUtime=1.39
/proc/21430/stat : 21430 (cudf2lp) R 21417 21417 1733 0 -1 4202496 14946 0 0 0 133 6 0 0 20 0 1 0 115368160 51892224 11547 18446744073709551615 4194304 5690517 140737108174080 140737108171720 4348966 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/21430/statm: 12669 11547 160 366 0 12300 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 59888

[startup+3.10027 s]
/proc/loadavg: 1.00 1.00 0.91 2/62 21430
/proc/meminfo: memFree=324424/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=0.02
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 699 2807 0 0 0 0 2 0 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048912 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21430] ppid=21417 vsize=114764 CPUtime=2.98
/proc/21430/stat : 21430 (cudf2lp) R 21417 21417 1733 0 -1 4202496 39317 0 0 0 282 16 0 0 20 0 1 0 115368160 117518336 28360 18446744073709551615 4194304 5690517 140737108174080 140737108171288 5058496 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/21430/statm: 28691 28360 173 366 0 28322 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 123976

[startup+6.30024 s]
/proc/loadavg: 1.00 1.00 0.91 2/62 21431
/proc/meminfo: memFree=259572/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=3.35
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 727 42127 0 0 0 0 315 20 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048912 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21431] ppid=21417 vsize=206012 CPUtime=2.82
/proc/21431/stat : 21431 (gringo) R 21417 21417 1733 0 -1 4202496 52887 0 0 0 262 20 0 0 20 0 1 0 115368504 210956288 43607 18446744073709551615 4194304 6531320 140734787099104 140734787095720 4358695 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21431/statm: 51503 43607 282 571 0 50924 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 215224

[startup+12.7003 s]
/proc/loadavg: 1.00 1.00 0.91 2/63 21433
/proc/meminfo: memFree=283116/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=8.71
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 769 155650 0 0 0 0 802 69 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048320 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21432] ppid=21417 vsize=143808 CPUtime=3.72
/proc/21432/stat : 21432 (unclasp) R 21417 21417 1733 0 -1 4202496 41689 0 0 0 359 13 0 0 20 0 1 0 115369051 147259392 35466 18446744073709551615 4194304 6012874 140735752075408 140735752074728 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 35952 35466 230 444 0 35500 0
[pid=21433] ppid=21417 vsize=22328 CPUtime=0.01
/proc/21433/stat : 21433 (parse.py) S 21417 21417 1733 0 -1 4202496 1382 0 0 0 0 1 0 0 20 0 1 0 115369051 22863872 1191 18446744073709551615 4194304 6642060 140735262608192 140735262606312 140519399094048 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21433/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 175348

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

[startup+12.8004 s]
/proc/loadavg: 1.00 1.00 0.91 2/63 21433
/proc/meminfo: memFree=283116/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=8.71
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 769 155650 0 0 0 0 802 69 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048320 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21432] ppid=21417 vsize=143808 CPUtime=3.82
/proc/21432/stat : 21432 (unclasp) R 21417 21417 1733 0 -1 4202496 41689 0 0 0 369 13 0 0 20 0 1 0 115369051 147259392 35466 18446744073709551615 4194304 6012874 140735752075408 140735752074728 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 35952 35466 230 444 0 35500 0
[pid=21433] ppid=21417 vsize=22328 CPUtime=0.01
/proc/21433/stat : 21433 (parse.py) S 21417 21417 1733 0 -1 4202496 1382 0 0 0 0 1 0 0 20 0 1 0 115369051 22863872 1191 18446744073709551615 4194304 6642060 140735262608192 140735262606312 140519399094048 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21433/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 175348

[startup+16.0003 s]
/proc/loadavg: 1.00 1.00 0.91 2/63 21433
/proc/meminfo: memFree=283116/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=8.71
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 769 155650 0 0 0 0 802 69 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048320 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21432] ppid=21417 vsize=143808 CPUtime=7
/proc/21432/stat : 21432 (unclasp) R 21417 21417 1733 0 -1 4202496 41689 0 0 0 687 13 0 0 20 0 1 0 115369051 147259392 35466 18446744073709551615 4194304 6012874 140735752075408 140735752074728 4300161 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 35952 35466 230 444 0 35500 0
[pid=21433] ppid=21417 vsize=22328 CPUtime=0.01
/proc/21433/stat : 21433 (parse.py) S 21417 21417 1733 0 -1 4202496 1382 0 0 0 0 1 0 0 20 0 1 0 115369051 22863872 1191 18446744073709551615 4194304 6642060 140735262608192 140735262606312 140519399094048 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21433/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 15.72
Current children cumulated vsize (KiB) 175348

[startup+17.6003 s]
/proc/loadavg: 1.00 1.00 0.91 2/63 21433
/proc/meminfo: memFree=283116/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=8.71
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 769 155650 0 0 0 0 802 69 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048320 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21432] ppid=21417 vsize=143808 CPUtime=8.59
/proc/21432/stat : 21432 (unclasp) R 21417 21417 1733 0 -1 4202496 41689 0 0 0 846 13 0 0 20 0 1 0 115369051 147259392 35466 18446744073709551615 4194304 6012874 140735752075408 140735752074728 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 35952 35466 230 444 0 35500 0
[pid=21433] ppid=21417 vsize=22328 CPUtime=0.01
/proc/21433/stat : 21433 (parse.py) S 21417 21417 1733 0 -1 4202496 1382 0 0 0 0 1 0 0 20 0 1 0 115369051 22863872 1191 18446744073709551615 4194304 6642060 140735262608192 140735262606312 140519399094048 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21433/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 17.31
Current children cumulated vsize (KiB) 175348

[startup+19.2003 s]
/proc/loadavg: 1.00 1.00 0.91 2/63 21433
/proc/meminfo: memFree=283116/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=8.71
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 769 155650 0 0 0 0 802 69 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048320 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21432] ppid=21417 vsize=143808 CPUtime=10.17
/proc/21432/stat : 21432 (unclasp) R 21417 21417 1733 0 -1 4202496 41689 0 0 0 1004 13 0 0 20 0 1 0 115369051 147259392 35466 18446744073709551615 4194304 6012874 140735752075408 140735752074728 4274970 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 35952 35466 230 444 0 35500 0
[pid=21433] ppid=21417 vsize=22328 CPUtime=0.01
/proc/21433/stat : 21433 (parse.py) S 21417 21417 1733 0 -1 4202496 1382 0 0 0 0 1 0 0 20 0 1 0 115369051 22863872 1191 18446744073709551615 4194304 6642060 140735262608192 140735262606312 140519399094048 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21433/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 18.89
Current children cumulated vsize (KiB) 175348

[startup+19.6003 s]
/proc/loadavg: 1.00 1.00 0.91 2/63 21433
/proc/meminfo: memFree=283116/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=8.71
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 769 155650 0 0 0 0 802 69 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048320 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21432] ppid=21417 vsize=143808 CPUtime=10.57
/proc/21432/stat : 21432 (unclasp) R 21417 21417 1733 0 -1 4202496 41689 0 0 0 1044 13 0 0 20 0 1 0 115369051 147259392 35466 18446744073709551615 4194304 6012874 140735752075408 140735752074728 4506598 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 35952 35466 230 444 0 35500 0
[pid=21433] ppid=21417 vsize=22328 CPUtime=0.01
/proc/21433/stat : 21433 (parse.py) S 21417 21417 1733 0 -1 4202496 1382 0 0 0 0 1 0 0 20 0 1 0 115369051 22863872 1191 18446744073709551615 4194304 6642060 140735262608192 140735262606312 140519399094048 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21433/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 19.29
Current children cumulated vsize (KiB) 175348

[startup+19.8003 s]
/proc/loadavg: 1.00 1.00 0.91 2/63 21433
/proc/meminfo: memFree=282992/1022884 swapFree=0/0
[pid=21417] ppid=21416 vsize=9212 CPUtime=8.71
/proc/21417/stat : 21417 (aspuncud-basic) S 21416 21417 1733 0 -1 4202496 769 155650 0 0 0 0 802 69 20 0 1 0 115368158 9433088 365 18446744073709551615 4194304 5129932 140735398050256 140735398048320 139640726008926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21417/statm: 2303 365 303 229 0 63 0
[pid=21432] ppid=21417 vsize=143808 CPUtime=10.77
/proc/21432/stat : 21432 (unclasp) R 21417 21417 1733 0 -1 4202496 41689 0 0 0 1064 13 0 0 20 0 1 0 115369051 147259392 35466 18446744073709551615 4194304 6012874 140735752075408 140735752074472 5256141 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 35952 35466 230 444 0 35500 0
[pid=21433] ppid=21417 vsize=22328 CPUtime=0.01
/proc/21433/stat : 21433 (parse.py) S 21417 21417 1733 0 -1 4202496 1382 0 0 0 0 1 0 0 20 0 1 0 115369051 22863872 1191 18446744073709551615 4194304 6642060 140735262608192 140735262606312 140519399094048 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21433/statm: 5582 1191 508 598 0 668 0
Current children cumulated CPU time (s) 19.49
Current children cumulated vsize (KiB) 175348

Child status: 0
Real time (s): 19.8921
CPU time (s): 19.6012
CPU user time (s): 18.7132
CPU system time (s): 0.888055
CPU usage (%): 98.5379
Max. virtual memory (cumulated for all children) (KiB): 484188

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.7132
system time used= 0.888055
maximum resident set size= 416956
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 199787
page faults= 0
swaps= 0
block input operations= 68464
block output operations= 53096
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 144
involuntary context switches= 2366

runsolver used 0.020001 second user time and 0.084005 second system time

The end