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/embedded/real/7f80e4f0-4fe9-11e0-acd7-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/7f80e4f0-4fe9-11e0-acd7-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/7f80e4f0-4fe9-11e0-acd7-00163e1e087d.cudf.result -sum(solution,installedsize),-count(removed) 

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.92 0.90 2/64 6074
/proc/meminfo: memFree=349000/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9204 CPUtime=0
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 115867456 9424896 332 18446744073709551615 4194304 5129932 140736833494608 140736833492072 139787472320288 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2301 332 272 229 0 61 0

[startup+0.136737 s]
/proc/loadavg: 0.85 0.92 0.90 2/64 6074
/proc/meminfo: memFree=349000/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=0.03
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 731 3614 0 0 0 0 3 0 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833493264 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200259 s]
/proc/loadavg: 0.85 0.92 0.90 2/64 6074
/proc/meminfo: memFree=349000/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=0.03
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 731 3614 0 0 0 0 3 0 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833493264 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300252 s]
/proc/loadavg: 0.85 0.92 0.90 2/64 6074
/proc/meminfo: memFree=349000/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=0.03
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 731 3614 0 0 0 0 3 0 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833493264 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700186 s]
/proc/loadavg: 0.85 0.92 0.90 2/64 6074
/proc/meminfo: memFree=349000/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=0.03
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 731 3614 0 0 0 0 3 0 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833493264 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 0.85 0.92 0.90 2/66 6090
/proc/meminfo: memFree=290448/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=0.03
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 731 3614 0 0 0 0 3 0 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833493264 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6090] ppid=6074 vsize=62096 CPUtime=1.43
/proc/6090/stat : 6090 (cudf2lp) R 6074 6074 1745 0 -1 4202496 20762 0 0 0 134 9 0 0 20 0 1 0 115867459 63586304 15234 18446744073709551615 4194304 5690517 140733462592512 140733462589512 4951870 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/6090/statm: 15524 15234 174 366 0 15155 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 71308

[startup+3.10026 s]
/proc/loadavg: 0.86 0.92 0.90 2/66 6091
/proc/meminfo: memFree=288340/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=1.5
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 756 24378 0 0 0 0 139 11 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833493264 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6091] ppid=6074 vsize=169200 CPUtime=1.55
/proc/6091/stat : 6091 (gringo) R 6074 6074 1745 0 -1 4202496 40740 0 0 0 143 12 0 0 20 0 1 0 115867610 173260800 36072 18446744073709551615 4194304 6531320 140733953153760 140733953150376 4358772 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6091/statm: 42300 36072 283 571 0 41721 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 178412

[startup+6.30032 s]
/proc/loadavg: 0.86 0.92 0.90 2/67 6093
/proc/meminfo: memFree=261424/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=3.44
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 794 70391 0 0 0 0 315 29 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833492672 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6092] ppid=6074 vsize=59180 CPUtime=2.76
/proc/6092/stat : 6092 (clasp) R 6074 6074 1745 0 -1 4202496 17128 0 0 0 271 5 0 0 20 0 1 0 115867805 60600320 14402 18446744073709551615 4194304 6238623 140734169262944 140734169259968 4586680 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6092/statm: 14795 14402 263 500 0 14292 0
[pid=6093] ppid=6074 vsize=22040 CPUtime=0.01
/proc/6093/stat : 6093 (parse.py) S 6074 6074 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115867805 22568960 1128 18446744073709551615 4194304 6642060 140735408595856 140735408594216 140438230157088 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6093/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 90432

[startup+12.7003 s]
/proc/loadavg: 0.88 0.92 0.90 2/67 6093
/proc/meminfo: memFree=261424/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=3.44
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 794 70391 0 0 0 0 315 29 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833492672 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6092] ppid=6074 vsize=59180 CPUtime=9.12
/proc/6092/stat : 6092 (clasp) R 6074 6074 1745 0 -1 4202496 17128 0 0 0 906 6 0 0 20 0 1 0 115867805 60600320 14402 18446744073709551615 4194304 6238623 140734169262944 140734169259968 4421797 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6092/statm: 14795 14402 263 500 0 14292 0
[pid=6093] ppid=6074 vsize=22040 CPUtime=0.01
/proc/6093/stat : 6093 (parse.py) S 6074 6074 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115867805 22568960 1128 18446744073709551615 4194304 6642060 140735408595856 140735408594216 140438230157088 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6093/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.57
Current children cumulated vsize (KiB) 90432

[startup+25.5003 s]
/proc/loadavg: 0.90 0.92 0.90 2/67 6093
/proc/meminfo: memFree=261176/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=3.44
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 794 70391 0 0 0 0 315 29 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833492672 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6092] ppid=6074 vsize=59180 CPUtime=21.82
/proc/6092/stat : 6092 (clasp) R 6074 6074 1745 0 -1 4202496 17201 0 0 0 2176 6 0 0 20 0 1 0 115867805 60600320 14475 18446744073709551615 4194304 6238623 140734169262944 140734169259968 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6092/statm: 14795 14475 263 500 0 14292 0
[pid=6093] ppid=6074 vsize=22040 CPUtime=0.01
/proc/6093/stat : 6093 (parse.py) S 6074 6074 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115867805 22568960 1128 18446744073709551615 4194304 6642060 140735408595856 140735408594216 140438230157088 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6093/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.27
Current children cumulated vsize (KiB) 90432

[startup+51.1003 s]
/proc/loadavg: 0.93 0.93 0.90 2/67 6093
/proc/meminfo: memFree=261052/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=3.44
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 794 70391 0 0 0 0 315 29 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833492672 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6092] ppid=6074 vsize=59180 CPUtime=47.23
/proc/6092/stat : 6092 (clasp) R 6074 6074 1745 0 -1 4202496 17201 0 0 0 4715 8 0 0 20 0 1 0 115867805 60600320 14475 18446744073709551615 4194304 6238623 140734169262944 140734169259968 4407237 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6092/statm: 14795 14475 263 500 0 14292 0
[pid=6093] ppid=6074 vsize=22040 CPUtime=0.01
/proc/6093/stat : 6093 (parse.py) S 6074 6074 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115867805 22568960 1128 18446744073709551615 4194304 6642060 140735408595856 140735408594216 140438230157088 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6093/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.68
Current children cumulated vsize (KiB) 90432

[startup+102.3 s]
/proc/loadavg: 0.97 0.94 0.91 2/67 6093
/proc/meminfo: memFree=260928/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=3.44
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 794 70391 0 0 0 0 315 29 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833492672 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6092] ppid=6074 vsize=59180 CPUtime=98.06
/proc/6092/stat : 6092 (clasp) R 6074 6074 1745 0 -1 4202496 17201 0 0 0 9796 10 0 0 20 0 1 0 115867805 60600320 14475 18446744073709551615 4194304 6238623 140734169262944 140734169259968 5448227 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6092/statm: 14795 14475 263 500 0 14292 0
[pid=6093] ppid=6074 vsize=22040 CPUtime=0.01
/proc/6093/stat : 6093 (parse.py) S 6074 6074 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115867805 22568960 1128 18446744073709551615 4194304 6642060 140735408595856 140735408594216 140438230157088 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6093/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.51
Current children cumulated vsize (KiB) 90432



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.2 s]
/proc/loadavg: 0.98 0.94 0.91 2/67 6093
/proc/meminfo: memFree=256712/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=3.44
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 794 70391 0 0 0 0 315 29 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833492672 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6092] ppid=6074 vsize=63428 CPUtime=146.6
/proc/6092/stat : 6092 (clasp) R 6074 6074 1745 0 -1 4202496 18275 0 0 0 14649 11 0 0 20 0 1 0 115867805 64950272 15549 18446744073709551615 4194304 6238623 140734169262944 140734169259968 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6092/statm: 15857 15549 263 500 0 15354 0
[pid=6093] ppid=6074 vsize=22040 CPUtime=0.01
/proc/6093/stat : 6093 (parse.py) S 6074 6074 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115867805 22568960 1128 18446744073709551615 4194304 6642060 140735408595856 140735408594216 140438230157088 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6093/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 94680

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.2 s]
/proc/loadavg: 0.98 0.94 0.91 2/67 6093
/proc/meminfo: memFree=256712/1022884 swapFree=0/0
[pid=6074] ppid=6073 vsize=9212 CPUtime=3.44
/proc/6074/stat : 6074 (aspcud-basic) S 6073 6074 1745 0 -1 4202496 794 70391 0 0 0 0 315 29 20 0 1 0 115867456 9433088 365 18446744073709551615 4194304 5129932 140736833494608 140736833492672 139787472176222 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6074/statm: 2303 365 303 229 0 63 0
[pid=6092] ppid=6074 vsize=63428 CPUtime=146.6
/proc/6092/stat : 6092 (clasp) R 6074 6074 1745 0 -1 4202496 18275 0 0 0 14649 11 0 0 20 0 1 0 115867805 64950272 15549 18446744073709551615 4194304 6238623 140734169262944 140734169259968 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6092/statm: 15857 15549 263 500 0 15354 0
[pid=6093] ppid=6074 vsize=22040 CPUtime=0.01
/proc/6093/stat : 6093 (parse.py) S 6074 6074 1745 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115867805 22568960 1128 18446744073709551615 4194304 6642060 140735408595856 140735408594216 140438230157088 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6093/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 94680

Child status: 0
Real time (s): 151.218
CPU time (s): 150.097
CPU user time (s): 149.657
CPU system time (s): 0.440027
CPU usage (%): 99.259
Max. virtual memory (cumulated for all children) (KiB): 200176

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.657
system time used= 0.440027
maximum resident set size= 165364
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 91082
page faults= 0
swaps= 0
block input operations= 32008
block output operations= 22808
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 69
involuntary context switches= 17197

runsolver used 0.260016 second user time and 0.568035 second system time

The end