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/201108311143/aspcud-1.5/a754ac72-95cc-11e0-9181-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//a754ac72-95cc-11e0-9181-00163e1e087d.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/a754ac72-95cc-11e0-9181-00163e1e087d.cudf.dudf-real.result -sum(installedsize) 

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.00 1.00 1/33 32284
/proc/meminfo: memFree=791692/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=3020 CPUtime=0
/proc/32284/stat : 32284 (runsolver) D 32283 32284 19908 34817 19908 4202560 72 0 0 0 0 0 0 0 25 0 1 0 66992331 3092480 94 1283457024 134512640 134586868 4294512800 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/32284/statm: 755 94 62 19 0 54 0

[startup+0.108116 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 32284
/proc/meminfo: memFree=791692/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=0
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 1522 0 3 0 0 0 0 25 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.20417 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 32284
/proc/meminfo: memFree=791692/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=0
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 1522 0 3 0 0 0 0 25 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.30413 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 32284
/proc/meminfo: memFree=791692/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=0
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 1522 0 3 0 0 0 0 25 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.70415 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 32284
/proc/meminfo: memFree=791692/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=0
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 1522 0 3 0 0 0 0 25 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.5042 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 32295
/proc/meminfo: memFree=762144/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=0
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 1522 0 3 0 0 0 0 25 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=1932 CPUtime=0
/proc/32293/stat : 32293 (clasp) S 32284 32284 19908 34817 19908 4202496 274 0 18 0 0 0 0 0 22 0 1 0 66992336 1978368 160 1283457024 134512640 136285277 4287890048 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/32293/statm: 483 160 144 433 0 48 0
[pid=32294] ppid=32284 vsize=2584 CPUtime=0
/proc/32294/stat : 32294 (gringo) S 32284 32284 19908 34817 19908 4202496 382 0 22 0 0 0 0 0 22 0 1 0 66992336 2646016 272 1283457024 134512640 136933539 4287894480 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/32294/statm: 646 272 242 592 0 51 0
[pid=32295] ppid=32284 vsize=26772 CPUtime=0.99
/proc/32295/stat : 32295 (cudf2lp) R 32284 32284 19908 34817 19908 4202496 7530 0 15 0 95 4 0 0 25 0 1 0 66992336 27414528 5947 1283457024 134512640 135786343 4288017104 18446744073709551615 134613449 0 0 6 0 0 0 0 17 0 0 0 0
/proc/32295/statm: 6693 5947 128 311 0 6380 0
Current children cumulated CPU time (s) 0.99
Current children cumulated vsize (KiB) 33880

[startup+3.10433 s]
/proc/loadavg: 1.00 1.00 1.00 3/36 32295
/proc/meminfo: memFree=765052/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=6208 CPUtime=0.9
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 1452 0 21 0 90 0 0 0 19 0 1 0 66992336 6356992 1338 1283457024 134512640 136285277 4287890048 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 1552 1338 234 433 0 1117 0
Current children cumulated CPU time (s) 2.58
Current children cumulated vsize (KiB) 8800

[startup+6.30499 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 32295
/proc/meminfo: memFree=762208/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=7660 CPUtime=4.09
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 1843 0 21 0 409 0 0 0 25 0 1 0 66992336 7843840 1709 1283457024 134512640 136285277 4287890048 18446744073709551615 134669902 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 1915 1709 234 433 0 1480 0
Current children cumulated CPU time (s) 5.77
Current children cumulated vsize (KiB) 10252

[startup+12.7062 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 32295
/proc/meminfo: memFree=761472/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=8312 CPUtime=10.49
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 2057 0 21 0 1049 0 0 0 25 0 1 0 66992336 8511488 1866 1283457024 134512640 136285277 4287890048 18446744073709551615 134959981 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 2078 1866 234 433 0 1643 0
Current children cumulated CPU time (s) 12.17
Current children cumulated vsize (KiB) 10904

[startup+25.5115 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 32295
/proc/meminfo: memFree=759736/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=9764 CPUtime=23.28
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 2578 0 21 0 2328 0 0 0 25 0 1 0 66992336 9998336 2234 1283457024 134512640 136285277 4287890048 18446744073709551615 134985131 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 2441 2234 234 433 0 2006 0
Current children cumulated CPU time (s) 24.96
Current children cumulated vsize (KiB) 12356

[startup+51.1073 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 32295
/proc/meminfo: memFree=759240/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=10372 CPUtime=48.87
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 2738 0 21 0 4887 0 0 0 25 0 1 0 66992336 10620928 2386 1283457024 134512640 136285277 4287890048 18446744073709551615 134966952 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 2593 2386 234 433 0 2158 0
Current children cumulated CPU time (s) 50.55
Current children cumulated vsize (KiB) 12964

[startup+102.309 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 32295
/proc/meminfo: memFree=758372/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=10640 CPUtime=100.05
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 3174 0 21 0 10005 0 0 0 25 0 1 0 66992336 10895360 2453 1283457024 134512640 136285277 4287890048 18446744073709551615 134615112 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 2660 2453 234 433 0 2225 0
Current children cumulated CPU time (s) 101.73
Current children cumulated vsize (KiB) 13232

[startup+162.312 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 32299
/proc/meminfo: memFree=757232/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=11520 CPUtime=160.02
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 4348 0 21 0 15999 3 0 0 25 0 1 0 66992336 11796480 2671 1283457024 134512640 136285277 4287890048 18446744073709551615 134946522 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 2880 2671 234 433 0 2445 0
Current children cumulated CPU time (s) 161.7
Current children cumulated vsize (KiB) 14112

[startup+222.315 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 32305
/proc/meminfo: memFree=756984/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=11948 CPUtime=220
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 4922 0 21 0 21997 3 0 0 25 0 1 0 66992336 12234752 2778 1283457024 134512640 136285277 4287890048 18446744073709551615 134964942 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 2987 2778 234 433 0 2552 0
Current children cumulated CPU time (s) 221.68
Current children cumulated vsize (KiB) 14540

[startup+282.308 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 32306
/proc/meminfo: memFree=757000/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=12296 CPUtime=279.93
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 5445 0 21 0 27989 4 0 0 25 0 1 0 66992336 12591104 2862 1283457024 134512640 136285277 4287890048 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 3074 2862 234 433 0 2639 0
Current children cumulated CPU time (s) 281.61
Current children cumulated vsize (KiB) 14888



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.709 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 32306
/proc/meminfo: memFree=756876/1048576 swapFree=0/0
[pid=32284] ppid=32283 vsize=2592 CPUtime=1.68
/proc/32284/stat : 32284 (aspcud-1.5) S 32283 32284 19908 34817 19908 4202496 575 14800 0 40 0 0 161 7 16 0 1 0 66992331 2654208 298 1283457024 134512640 135304128 4291612336 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32284/statm: 648 298 251 194 0 35 0
[pid=32293] ppid=32284 vsize=12280 CPUtime=288.33
/proc/32293/stat : 32293 (clasp) R 32284 32284 19908 34817 19908 4202496 5509 0 21 0 28829 4 0 0 25 0 1 0 66992336 12574720 2861 1283457024 134512640 136285277 4287890048 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32293/statm: 3070 2861 234 433 0 2635 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 14872

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

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

Child status: 0
Real time (s): 290.75
CPU time (s): 290.038
CPU user time (s): 289.922
CPU system time (s): 0.116007
CPU usage (%): 99.7551
Max. virtual memory (cumulated for all children) (KiB): 49824

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.922
system time used= 0.116007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 24433
page faults= 62
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 272
involuntary context switches= 3711

runsolver used 0 second user time and 0 second system time

The end