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 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/install/rand446.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand446.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/install/rand446.cudf.result -notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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

[startup+0 s]
/proc/loadavg: 1.00 1.05 1.07 2/64 11557
/proc/meminfo: memFree=699380/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=3152 CPUtime=0
/proc/11557/stat : 11557 (runsolver) R 11556 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117934052 3227648 32 18446744073709551615 134512640 134586868 4288223824 4288221872 4151354416 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.186944 s]
/proc/loadavg: 1.00 1.05 1.07 2/64 11557
/proc/meminfo: memFree=699380/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=0.03
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 740 3617 0 0 0 0 2 1 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200339 s]
/proc/loadavg: 1.00 1.05 1.07 2/64 11557
/proc/meminfo: memFree=699380/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=0.03
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 740 3617 0 0 0 0 2 1 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300308 s]
/proc/loadavg: 1.00 1.05 1.07 2/64 11557
/proc/meminfo: memFree=699380/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=0.03
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 740 3617 0 0 0 0 2 1 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70024 s]
/proc/loadavg: 1.00 1.05 1.07 2/64 11557
/proc/meminfo: memFree=699380/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=0.03
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 740 3617 0 0 0 0 2 1 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 1.00 1.05 1.07 2/66 11573
/proc/meminfo: memFree=661784/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=0.03
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 740 3617 0 0 0 0 2 1 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11573] ppid=11557 vsize=53756 CPUtime=1.39
/proc/11573/stat : 11573 (cudf2lp) R 11557 11557 1745 0 -1 4202496 15195 0 0 0 131 8 0 0 20 0 1 0 117934054 55046144 11796 18446744073709551615 4194304 5690517 140736058343024 140736058340664 4360758 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/11573/statm: 13439 11796 160 366 0 13070 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 62968

[startup+3.10031 s]
/proc/loadavg: 1.00 1.05 1.07 2/66 11573
/proc/meminfo: memFree=621236/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=0.03
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 740 3617 0 0 0 0 2 1 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11573] ppid=11557 vsize=99144 CPUtime=2.95
/proc/11573/stat : 11573 (cudf2lp) R 11557 11557 1745 0 -1 4202496 28554 0 0 0 278 17 0 0 20 0 1 0 117934054 101523456 21826 18446744073709551615 4194304 5690517 140736058343024 140736058340664 4293705 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/11573/statm: 24786 21826 160 366 0 24417 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 108356

[startup+6.30028 s]
/proc/loadavg: 1.00 1.05 1.07 2/66 11574
/proc/meminfo: memFree=634132/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=4.82
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 766 44897 0 0 0 0 450 32 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11574] ppid=11557 vsize=40844 CPUtime=1.34
/proc/11574/stat : 11574 (gringo) R 11557 11557 1745 0 -1 4202496 11883 0 0 0 127 7 0 0 20 0 1 0 117934546 41824256 8749 18446744073709551615 4194304 6531320 140734731550880 140734731547496 4341016 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/11574/statm: 10211 8749 259 571 0 9632 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 50056

[startup+12.7003 s]
/proc/loadavg: 1.00 1.05 1.07 2/66 11574
/proc/meminfo: memFree=225924/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=4.82
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 766 44897 0 0 0 0 450 32 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11574] ppid=11557 vsize=573964 CPUtime=7.68
/proc/11574/stat : 11574 (gringo) R 11557 11557 1745 0 -1 4202496 134924 0 0 0 720 48 0 0 20 0 1 0 117934546 587739136 116426 18446744073709551615 4194304 6531320 140734731550880 140734731547864 5520790 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/11574/statm: 143491 116426 282 571 0 142912 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 583176

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

[startup+12.8003 s]
/proc/loadavg: 1.00 1.05 1.07 2/66 11574
/proc/meminfo: memFree=225924/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=4.82
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 766 44897 0 0 0 0 450 32 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894170464 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11574] ppid=11557 vsize=581420 CPUtime=7.78
/proc/11574/stat : 11574 (gringo) R 11557 11557 1745 0 -1 4202496 136587 0 0 0 730 48 0 0 20 0 1 0 117934546 595374080 118089 18446744073709551615 4194304 6531320 140734731550880 140734731547496 5632288 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/11574/statm: 145355 118089 282 571 0 144776 0
Current children cumulated CPU time (s) 12.6
Current children cumulated vsize (KiB) 590632

[startup+14.4065 s]
/proc/loadavg: 1.00 1.05 1.07 2/67 11576
/proc/meminfo: memFree=467220/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=13.29
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 807 182867 0 0 0 0 1235 94 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894169872 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11575] ppid=11557 vsize=173692 CPUtime=0.89
/proc/11575/stat : 11575 (clasp) R 11557 11557 1745 0 -1 4202496 48032 0 0 0 75 14 0 0 20 0 1 0 117935400 177860608 41795 18446744073709551615 4194304 6238623 140735356432320 140735356429800 4471251 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/11575/statm: 43423 41795 232 500 0 42920 0
[pid=11576] ppid=11557 vsize=22040 CPUtime=0.01
/proc/11576/stat : 11576 (parse.py) S 11557 11557 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 117935400 22568960 1128 18446744073709551615 4194304 6642060 140735543132880 140735543131240 140464274843424 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/11576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14.19
Current children cumulated vsize (KiB) 204944

[startup+15.2003 s]
/proc/loadavg: 1.00 1.05 1.07 2/67 11576
/proc/meminfo: memFree=467220/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=13.29
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 807 182867 0 0 0 0 1235 94 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894169872 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11575] ppid=11557 vsize=165000 CPUtime=1.68
/proc/11575/stat : 11575 (clasp) R 11557 11557 1745 0 -1 4202496 48967 0 0 0 154 14 0 0 20 0 1 0 117935400 168960000 40419 18446744073709551615 4194304 6238623 140735356432320 140735356430016 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/11575/statm: 41250 40419 263 500 0 40747 0
[pid=11576] ppid=11557 vsize=22040 CPUtime=0.01
/proc/11576/stat : 11576 (parse.py) S 11557 11557 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 117935400 22568960 1128 18446744073709551615 4194304 6642060 140735543132880 140735543131240 140464274843424 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/11576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14.98
Current children cumulated vsize (KiB) 196252

[startup+15.6003 s]
/proc/loadavg: 1.00 1.05 1.07 2/67 11576
/proc/meminfo: memFree=467468/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=13.29
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 807 182867 0 0 0 0 1235 94 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894169872 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11575] ppid=11557 vsize=165000 CPUtime=2.07
/proc/11575/stat : 11575 (clasp) R 11557 11557 1745 0 -1 4202496 48967 0 0 0 193 14 0 0 20 0 1 0 117935400 168960000 40419 18446744073709551615 4194304 6238623 140735356432320 140735356429344 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/11575/statm: 41250 40419 263 500 0 40747 0
[pid=11576] ppid=11557 vsize=22040 CPUtime=0.01
/proc/11576/stat : 11576 (parse.py) S 11557 11557 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 117935400 22568960 1128 18446744073709551615 4194304 6642060 140735543132880 140735543131240 140464274843424 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/11576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 15.37
Current children cumulated vsize (KiB) 196252

[startup+16.0003 s]
/proc/loadavg: 1.00 1.05 1.07 2/67 11576
/proc/meminfo: memFree=467468/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=13.29
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 807 182867 0 0 0 0 1235 94 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894169872 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
[pid=11575] ppid=11557 vsize=165000 CPUtime=2.47
/proc/11575/stat : 11575 (clasp) R 11557 11557 1745 0 -1 4202496 48968 0 0 0 232 15 0 0 20 0 1 0 117935400 168960000 40420 18446744073709551615 4194304 6238623 140735356432320 140735356429344 4586608 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/11575/statm: 41250 40420 264 500 0 40747 0
[pid=11576] ppid=11557 vsize=22040 CPUtime=0.01
/proc/11576/stat : 11576 (parse.py) S 11557 11557 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 117935400 22568960 1128 18446744073709551615 4194304 6642060 140735543132880 140735543131240 140464274843424 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/11576/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 15.77
Current children cumulated vsize (KiB) 196252

[startup+16.1003 s]
/proc/loadavg: 1.00 1.05 1.07 2/67 11576
/proc/meminfo: memFree=467468/1022884 swapFree=0/0
[pid=11557] ppid=11556 vsize=9212 CPUtime=15.87
/proc/11557/stat : 11557 (aspcud-full) S 11556 11557 1745 0 -1 4202496 841 233189 0 0 0 0 1474 113 20 0 1 0 117934052 9433088 365 18446744073709551615 4194304 5129932 140734894171808 140734894169360 140138710963294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11557/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 15.87
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 16.1026
CPU time (s): 15.897
CPU user time (s): 14.7529
CPU system time (s): 1.14407
CPU usage (%): 98.7229
Max. virtual memory (cumulated for all children) (KiB): 596708

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.7529
system time used= 1.14407
maximum resident set size= 477872
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 234267
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 66336
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 76
involuntary context switches= 1854

runsolver used 0.044002 second user time and 0.060003 second system time

The end