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/201108300820/aspuncud-user-1.0/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/ab9005be-bacc-11e0-b0f6-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.03 1.00 1/35 14583
/proc/meminfo: memFree=940916/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=3024 CPUtime=0
/proc/14583/stat : 14583 (runsolver) D 14582 14583 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 57461940 3096576 94 1283457024 134512640 134586868 4287386048 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/14583/statm: 756 94 62 19 0 55 0

[startup+0.195301 s]
/proc/loadavg: 1.00 1.03 1.00 1/35 14583
/proc/meminfo: memFree=940916/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=0
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.207389 s]
/proc/loadavg: 1.00 1.03 1.00 1/35 14583
/proc/meminfo: memFree=940916/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=0
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.313341 s]
/proc/loadavg: 1.00 1.03 1.00 1/35 14583
/proc/meminfo: memFree=940916/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=0
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.713436 s]
/proc/loadavg: 1.00 1.03 1.00 1/35 14583
/proc/meminfo: memFree=940916/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=0
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51355 s]
/proc/loadavg: 1.00 1.03 1.00 2/39 14594
/proc/meminfo: memFree=912864/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=0
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=3440 CPUtime=0
/proc/14592/stat : 14592 (unclasp) S 14583 14583 2160 34817 2160 4202496 401 0 5 0 0 0 0 0 25 0 1 0 57461945 3522560 271 1283457024 134512640 135121179 4289949888 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14592/statm: 860 271 240 149 0 51 0
[pid=14593] ppid=14583 vsize=2692 CPUtime=0
/proc/14593/stat : 14593 (gringo) S 14583 14583 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 24 0 1 0 57461945 2756608 281 1283457024 134512640 137056543 4289948640 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14593/statm: 673 281 252 622 0 48 0
[pid=14594] ppid=14583 vsize=27300 CPUtime=1.29
/proc/14594/stat : 14594 (cudf2lp) R 14583 14583 2160 34817 2160 4202496 7784 0 15 0 126 3 0 0 25 0 1 0 57461945 27955200 6304 1283457024 134512640 135786343 4288527712 18446744073709551615 134586033 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14594/statm: 6825 6304 128 311 0 6512 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 36028

[startup+3.1138 s]
/proc/loadavg: 1.00 1.03 1.00 4/39 14594
/proc/meminfo: memFree=888872/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=0
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=18564 CPUtime=0.04
/proc/14592/stat : 14592 (unclasp) S 14583 14583 2160 34817 2160 4202496 4816 0 6 0 2 2 0 0 18 0 1 0 57461945 19009536 4029 1283457024 134512640 135121179 4289949888 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14592/statm: 4641 4029 275 149 0 3832 0
[pid=14593] ppid=14583 vsize=22708 CPUtime=0.79
/proc/14593/stat : 14593 (gringo) R 14583 14583 2160 34817 2160 4202496 6927 0 23 0 74 5 0 0 18 0 1 0 57461945 23252992 4683 1283457024 134512640 137056543 4289948640 18446744073709551615 134554213 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14593/statm: 5677 4683 253 622 0 5052 0
[pid=14594] ppid=14583 vsize=43540 CPUtime=2.05
/proc/14594/stat : 14594 (cudf2lp) R 14583 14583 2160 34817 2160 4202496 13443 0 15 0 201 4 0 0 25 0 1 0 57461945 44584960 10693 1283457024 134512640 135786343 4288527712 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14594/statm: 10885 10693 139 311 0 10572 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 87408

[startup+6.3046 s]
/proc/loadavg: 1.00 1.03 1.00 3/39 14595
/proc/meminfo: memFree=794260/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=2.58
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 14963 0 18 0 0 250 8 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=68144 CPUtime=0.3
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 19185 0 6 0 28 2 0 0 18 0 1 0 57461945 69779456 16227 1283457024 134512640 135121179 4289949888 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 17036 16227 277 149 0 16227 0
[pid=14593] ppid=14583 vsize=89680 CPUtime=3.2
/proc/14593/stat : 14593 (gringo) R 14583 14583 2160 34817 2160 4202496 29609 0 23 0 306 14 0 0 18 0 1 0 57461945 91832320 18705 1283457024 134512640 137056543 4289948640 18446744073709551615 134610618 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14593/statm: 22420 18705 268 622 0 21795 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 160420

[startup+12.7077 s]
/proc/loadavg: 1.07 1.04 1.00 2/37 14595
/proc/meminfo: memFree=811784/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=131072 CPUtime=4.8
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 98633 0 7 0 443 37 0 0 25 0 1 0 57461945 134217728 30445 1283457024 134512640 135121179 4289949888 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 32768 30445 319 149 0 31959 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 133668

[startup+25.5117 s]
/proc/loadavg: 1.06 1.04 1.00 2/37 14597
/proc/meminfo: memFree=815256/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=134204 CPUtime=17.6
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 353162 0 7 0 1618 142 0 0 25 0 1 0 57461945 137424896 30655 1283457024 134512640 135121179 4289949888 18446744073709551615 134990522 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 33551 30655 319 149 0 32742 0
Current children cumulated CPU time (s) 25.27
Current children cumulated vsize (KiB) 136800

[startup+51.1104 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 14599
/proc/meminfo: memFree=815256/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=135016 CPUtime=43.18
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 847416 0 7 0 3947 371 0 0 25 0 1 0 57461945 138256384 31430 1283457024 134512640 135121179 4289949888 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 33754 31430 319 149 0 32945 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 137612

[startup+102.307 s]
/proc/loadavg: 1.01 1.03 1.00 2/36 14600
/proc/meminfo: memFree=815148/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=131088 CPUtime=94.34
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 1824547 0 7 0 8659 775 0 0 25 0 1 0 57461945 134234112 30486 1283457024 134512640 135121179 4289949888 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 32772 30486 321 149 0 31963 0
Current children cumulated CPU time (s) 102.01
Current children cumulated vsize (KiB) 133684

[startup+162.308 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 14600
/proc/meminfo: memFree=814908/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=131100 CPUtime=154.29
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 2948027 0 7 0 14166 1263 0 0 25 0 1 0 57461945 134246400 30509 1283457024 134512640 135121179 4289949888 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 32775 30509 321 149 0 31966 0
Current children cumulated CPU time (s) 161.96
Current children cumulated vsize (KiB) 133696

[startup+222.307 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 14600
/proc/meminfo: memFree=814784/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=131104 CPUtime=214.24
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 4051633 0 7 0 19716 1708 0 0 25 0 1 0 57461945 134250496 30528 1283457024 134512640 135121179 4289949888 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 32776 30528 321 149 0 31967 0
Current children cumulated CPU time (s) 221.91
Current children cumulated vsize (KiB) 133700

[startup+282.306 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 14600
/proc/meminfo: memFree=811932/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=131476 CPUtime=274.21
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 5138434 0 7 0 25257 2164 0 0 25 0 1 0 57461945 134631424 30516 1283457024 134512640 135121179 4289949888 18446744073709551615 134638611 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 32869 30516 321 149 0 32060 0
Current children cumulated CPU time (s) 281.88
Current children cumulated vsize (KiB) 134072



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.51 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 14600
/proc/meminfo: memFree=814660/1048576 swapFree=0/0
[pid=14583] ppid=14582 vsize=2596 CPUtime=7.67
/proc/14583/stat : 14583 (aspuncud-user-1) S 14582 14583 2160 34817 2160 4202496 572 63385 0 41 0 0 737 30 18 0 1 0 57461940 2658304 298 1283457024 134512640 135304128 4287144544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14583/statm: 649 298 251 194 0 36 0
[pid=14592] ppid=14583 vsize=131480 CPUtime=282.41
/proc/14592/stat : 14592 (unclasp) R 14583 14583 2160 34817 2160 4202496 5284752 0 7 0 26016 2225 0 0 25 0 1 0 57461945 134635520 30549 1283457024 134512640 135121179 4289949888 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14592/statm: 32870 30549 321 149 0 32061 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 134076

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.549
CPU time (s): 290.11
CPU user time (s): 267.537
CPU system time (s): 22.5734
CPU usage (%): 99.8489
Max. virtual memory (cumulated for all children) (KiB): 250468

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 267.537
system time used= 22.5734
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5351095
page faults= 50
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 9606
involuntary context switches= 11312

runsolver used 0 second user time and 0.004 second system time

The end