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/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/8b0e7c16-bab4-11e0-a883-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/35 14080
/proc/meminfo: memFree=940868/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=3024 CPUtime=0
/proc/14080/stat : 14080 (runsolver) D 14079 14080 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 57182194 3096576 94 1283457024 134512640 134586868 4291966496 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/14080/statm: 756 94 62 19 0 55 0

[startup+0.15124 s]
/proc/loadavg: 1.00 1.00 1.00 1/35 14080
/proc/meminfo: memFree=940868/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=0
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.207261 s]
/proc/loadavg: 1.00 1.00 1.00 1/35 14080
/proc/meminfo: memFree=940868/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=0
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.307257 s]
/proc/loadavg: 1.00 1.00 1.00 1/35 14080
/proc/meminfo: memFree=940868/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=0
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.709439 s]
/proc/loadavg: 1.00 1.00 1.00 1/35 14080
/proc/meminfo: memFree=940868/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=0
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50969 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 14091
/proc/meminfo: memFree=912824/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=0
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=3444 CPUtime=0
/proc/14089/stat : 14089 (unclasp) S 14080 14080 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 57182199 3526656 271 1283457024 134512640 135121179 4291205984 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14089/statm: 861 271 240 149 0 52 0
[pid=14090] ppid=14080 vsize=2692 CPUtime=0
/proc/14090/stat : 14090 (gringo) S 14080 14080 2160 34817 2160 4202496 385 0 24 0 0 0 0 0 24 0 1 0 57182199 2756608 281 1283457024 134512640 137056543 4290502080 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14090/statm: 673 281 252 622 0 48 0
[pid=14091] ppid=14080 vsize=27304 CPUtime=1.28
/proc/14091/stat : 14091 (cudf2lp) R 14080 14080 2160 34817 2160 4202496 7760 0 15 0 125 3 0 0 25 0 1 0 57182199 27959296 6279 1283457024 134512640 135786343 4293718336 18446744073709551615 134566216 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14091/statm: 6826 6279 128 311 0 6513 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 36032

[startup+3.10998 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 14091
/proc/meminfo: memFree=889452/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=0
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=18176 CPUtime=0.03
/proc/14089/stat : 14089 (unclasp) S 14080 14080 2160 34817 2160 4202496 4708 0 6 0 1 2 0 0 18 0 1 0 57182199 18612224 3920 1283457024 134512640 135121179 4291205984 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14089/statm: 4544 3920 275 149 0 3735 0
[pid=14090] ppid=14080 vsize=22444 CPUtime=0.79
/proc/14090/stat : 14090 (gringo) R 14080 14080 2160 34817 2160 4202496 6814 0 24 0 76 3 0 0 18 0 1 0 57182199 22982656 4570 1283457024 134512640 137056543 4290502080 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14090/statm: 5611 4570 253 622 0 4986 0
[pid=14091] ppid=14080 vsize=43544 CPUtime=2.04
/proc/14091/stat : 14091 (cudf2lp) R 14080 14080 2160 34817 2160 4202496 13445 0 15 0 198 6 0 0 25 0 1 0 57182199 44589056 10694 1283457024 134512640 135786343 4293718336 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14091/statm: 10886 10694 139 311 0 10573 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 86756

[startup+6.31078 s]
/proc/loadavg: 1.08 1.02 1.01 3/39 14092
/proc/meminfo: memFree=794964/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=2.65
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 14963 0 18 0 0 259 6 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=66832 CPUtime=0.19
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 18865 0 6 0 16 3 0 0 18 0 1 0 57182199 68435968 15906 1283457024 134512640 135121179 4291205984 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 16708 15906 277 149 0 15899 0
[pid=14090] ppid=14080 vsize=89680 CPUtime=3.22
/proc/14090/stat : 14090 (gringo) R 14080 14080 2160 34817 2160 4202496 29582 0 24 0 308 14 0 0 18 0 1 0 57182199 91832320 18678 1283457024 134512640 137056543 4290502080 18446744073709551615 135918139 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14090/statm: 22420 18678 268 622 0 21795 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 159104

[startup+12.713 s]
/proc/loadavg: 1.07 1.02 1.00 2/37 14092
/proc/meminfo: memFree=811744/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=131080 CPUtime=4.75
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 100517 0 7 0 439 36 0 0 25 0 1 0 57182199 134225920 30447 1283457024 134512640 135121179 4291205984 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 32770 30447 319 149 0 31961 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 133672

[startup+25.5068 s]
/proc/loadavg: 1.06 1.02 1.00 2/37 14094
/proc/meminfo: memFree=815216/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=131092 CPUtime=17.54
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 354853 0 7 0 1616 138 0 0 25 0 1 0 57182199 134238208 30457 1283457024 134512640 135121179 4291205984 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 32773 30457 319 149 0 31964 0
Current children cumulated CPU time (s) 25.24
Current children cumulated vsize (KiB) 133684

[startup+51.105 s]
/proc/loadavg: 1.04 1.01 1.00 2/37 14096
/proc/meminfo: memFree=815216/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=134212 CPUtime=43.13
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 856459 0 7 0 3984 329 0 0 25 0 1 0 57182199 137433088 31147 1283457024 134512640 135121179 4291205984 18446744073709551615 134990531 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 33553 31147 319 149 0 32744 0
Current children cumulated CPU time (s) 50.83
Current children cumulated vsize (KiB) 136804

[startup+102.302 s]
/proc/loadavg: 1.01 1.01 1.00 2/36 14096
/proc/meminfo: memFree=815108/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=131096 CPUtime=94.29
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 1837854 0 7 0 8693 736 0 0 25 0 1 0 57182199 134242304 30485 1283457024 134512640 135121179 4291205984 18446744073709551615 134747624 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 32774 30485 321 149 0 31965 0
Current children cumulated CPU time (s) 101.99
Current children cumulated vsize (KiB) 133688

[startup+162.303 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 14096
/proc/meminfo: memFree=811768/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=131108 CPUtime=154.24
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 2946119 0 7 0 14227 1197 0 0 25 0 1 0 57182199 134254592 30511 1283457024 134512640 135121179 4291205984 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 32777 30511 321 149 0 31968 0
Current children cumulated CPU time (s) 161.94
Current children cumulated vsize (KiB) 133700

[startup+222.312 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 14096
/proc/meminfo: memFree=814744/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=131112 CPUtime=214.2
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 4057390 0 7 0 19749 1671 0 0 25 0 1 0 57182199 134258688 30530 1283457024 134512640 135121179 4291205984 18446744073709551615 134873565 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 32778 30530 321 149 0 31969 0
Current children cumulated CPU time (s) 221.9
Current children cumulated vsize (KiB) 133704

[startup+282.313 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 14096
/proc/meminfo: memFree=814496/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=131484 CPUtime=274.14
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 5136542 0 7 0 25294 2120 0 0 25 0 1 0 57182199 134639616 30547 1283457024 134512640 135121179 4291205984 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 32871 30547 321 149 0 32062 0
Current children cumulated CPU time (s) 281.84
Current children cumulated vsize (KiB) 134076



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.506 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 14096
/proc/meminfo: memFree=814496/1048576 swapFree=0/0
[pid=14080] ppid=14079 vsize=2592 CPUtime=7.7
/proc/14080/stat : 14080 (aspuncud-user-1) S 14079 14080 2160 34817 2160 4202496 574 63385 0 42 0 0 742 28 18 0 1 0 57182194 2654208 298 1283457024 134512640 135304128 4291614368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14080/statm: 648 298 251 194 0 35 0
[pid=14089] ppid=14080 vsize=131488 CPUtime=282.32
/proc/14089/stat : 14089 (unclasp) R 14080 14080 2160 34817 2160 4202496 5282810 0 7 0 26057 2175 0 0 25 0 1 0 57182199 134643712 30532 1283457024 134512640 135121179 4291205984 18446744073709551615 134747624 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14089/statm: 32872 30532 321 149 0 32063 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 134080

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.548
CPU time (s): 290.062
CPU user time (s): 268.009
CPU system time (s): 22.0534
CPU usage (%): 99.8327
Max. virtual memory (cumulated for all children) (KiB): 249888

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 268.009
system time used= 22.0534
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5349165
page faults= 51
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 9624
involuntary context switches= 11325

runsolver used 0 second user time and 0.004 second system time

The end