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/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/dd08e73e-d489-11df-b9cf-00163e3d3b7c.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.02 1.00 1/33 16940
/proc/meminfo: memFree=942564/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=3024 CPUtime=0
/proc/16940/stat : 16940 (runsolver) D 16939 16940 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 58760871 3096576 94 1283457024 134512640 134586868 4286859584 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/16940/statm: 756 94 62 19 0 55 0

[startup+0.163332 s]
/proc/loadavg: 1.00 1.02 1.00 1/33 16940
/proc/meminfo: memFree=942564/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=0
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 1516 0 3 0 0 0 0 25 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.20736 s]
/proc/loadavg: 1.00 1.02 1.00 1/33 16940
/proc/meminfo: memFree=942564/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=0
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 1516 0 3 0 0 0 0 25 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.310402 s]
/proc/loadavg: 1.00 1.02 1.00 1/33 16940
/proc/meminfo: memFree=942564/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=0
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 1516 0 3 0 0 0 0 25 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.710482 s]
/proc/loadavg: 1.00 1.02 1.00 1/33 16940
/proc/meminfo: memFree=942564/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=0
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 1516 0 3 0 0 0 0 25 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.51064 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 16951
/proc/meminfo: memFree=914264/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=0
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 1516 0 3 0 0 0 0 25 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=3444 CPUtime=0
/proc/16949/stat : 16949 (unclasp) S 16940 16940 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 25 0 1 0 58760875 3526656 272 1283457024 134512640 135121179 4286744448 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16949/statm: 861 272 240 149 0 52 0
[pid=16950] ppid=16940 vsize=2692 CPUtime=0
/proc/16950/stat : 16950 (gringo) S 16940 16940 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 58760876 2756608 281 1283457024 134512640 137056543 4290340512 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16950/statm: 673 281 252 622 0 48 0
[pid=16951] ppid=16940 vsize=27644 CPUtime=1.3
/proc/16951/stat : 16951 (cudf2lp) R 16940 16940 2160 34817 2160 4202496 8066 0 15 0 128 2 0 0 25 0 1 0 58760876 28307456 6342 1283457024 134512640 135786343 4286740000 18446744073709551615 134614710 0 0 6 0 0 0 0 17 0 0 0 0
/proc/16951/statm: 6911 6342 128 311 0 6598 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 36372

[startup+3.11097 s]
/proc/loadavg: 1.00 1.02 1.00 3/37 16951
/proc/meminfo: memFree=888784/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=0
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 1516 0 3 0 0 0 0 25 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=22296 CPUtime=0.07
/proc/16949/stat : 16949 (unclasp) S 16940 16940 2160 34817 2160 4202496 6018 0 6 0 3 4 0 0 18 0 1 0 58760875 22831104 4824 1283457024 134512640 135121179 4286744448 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16949/statm: 5574 4824 275 149 0 4765 0
[pid=16950] ppid=16940 vsize=31092 CPUtime=1.03
/proc/16950/stat : 16950 (gringo) R 16940 16940 2160 34817 2160 4202496 9313 0 23 0 100 3 0 0 18 0 1 0 58760876 31838208 5914 1283457024 134512640 137056543 4290340512 18446744073709551615 134694129 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16950/statm: 7773 5914 253 622 0 7148 0
[pid=16951] ppid=16940 vsize=36992 CPUtime=1.77
/proc/16951/stat : 16951 (cudf2lp) R 16940 16940 2160 34817 2160 4202496 11841 0 15 0 175 2 0 0 25 0 1 0 58760876 37879808 9052 1283457024 134512640 135786343 4286740000 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/16951/statm: 9248 9052 139 311 0 8935 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 92972

[startup+6.31182 s]
/proc/loadavg: 1.08 1.04 1.01 3/36 16951
/proc/meminfo: memFree=812912/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=2.13
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 13360 0 18 0 0 206 7 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=71508 CPUtime=0.49
/proc/16949/stat : 16949 (unclasp) S 16940 16940 2160 34817 2160 4202496 19498 0 6 0 43 6 0 0 18 0 1 0 58760875 73224192 17142 1283457024 134512640 135121179 4286744448 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16949/statm: 17877 17142 277 149 0 17068 0
[pid=16950] ppid=16940 vsize=116780 CPUtime=3.46
/proc/16950/stat : 16950 (gringo) R 16940 16940 2160 34817 2160 4202496 36076 0 23 0 334 12 0 0 19 0 1 0 58760876 119582720 23751 1283457024 134512640 137056543 4290340512 18446744073709551615 134612710 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16950/statm: 29195 23751 268 622 0 28570 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 190880

[startup+12.7139 s]
/proc/loadavg: 1.07 1.04 1.00 2/35 16951
/proc/meminfo: memFree=840960/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=105524 CPUtime=6.23
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 114265 0 7 0 576 47 0 0 25 0 1 0 58760875 108056576 24495 1283457024 134512640 135121179 4286744448 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 26381 24495 319 149 0 25572 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 108116

[startup+25.5078 s]
/proc/loadavg: 1.06 1.03 1.00 2/35 16951
/proc/meminfo: memFree=838232/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=105528 CPUtime=19.01
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 331345 0 7 0 1761 140 0 0 25 0 1 0 58760875 108060672 24505 1283457024 134512640 135121179 4286744448 18446744073709551615 134734462 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 26382 24505 321 149 0 25573 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 108120

[startup+51.106 s]
/proc/loadavg: 1.04 1.03 1.00 2/35 16951
/proc/meminfo: memFree=840712/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=108852 CPUtime=44.59
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 760568 0 7 0 4147 312 0 0 25 0 1 0 58760875 111464448 25370 1283457024 134512640 135121179 4286744448 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 27213 25370 321 149 0 26404 0
Current children cumulated CPU time (s) 50.84
Current children cumulated vsize (KiB) 111444

[startup+102.307 s]
/proc/loadavg: 1.01 1.02 1.00 2/35 16951
/proc/meminfo: memFree=839720/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=105980 CPUtime=95.73
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 1587775 0 7 0 8882 691 0 0 25 0 1 0 58760875 108523520 24701 1283457024 134512640 135121179 4286744448 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 26495 24701 321 149 0 25686 0
Current children cumulated CPU time (s) 101.98
Current children cumulated vsize (KiB) 108572

[startup+162.307 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 16951
/proc/meminfo: memFree=838232/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=105556 CPUtime=155.67
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 2539832 0 7 0 14485 1082 0 0 25 0 1 0 58760875 108089344 24640 1283457024 134512640 135121179 4286744448 18446744073709551615 4158956645 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 26389 24640 321 149 0 25580 0
Current children cumulated CPU time (s) 161.92
Current children cumulated vsize (KiB) 108148

[startup+222.31 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 16953
/proc/meminfo: memFree=839944/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=106004 CPUtime=215.62
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 3476867 0 7 0 20077 1485 0 0 25 0 1 0 58760875 108548096 24696 1283457024 134512640 135121179 4286744448 18446744073709551615 134849051 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 26501 24696 321 149 0 25692 0
Current children cumulated CPU time (s) 221.87
Current children cumulated vsize (KiB) 108596

[startup+282.311 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 16959
/proc/meminfo: memFree=839076/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=106020 CPUtime=275.59
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 4397292 0 7 0 25675 1884 0 0 25 0 1 0 58760875 108564480 24719 1283457024 134512640 135121179 4286744448 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 26505 24719 321 149 0 25696 0
Current children cumulated CPU time (s) 281.84
Current children cumulated vsize (KiB) 108612



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.514 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 16960
/proc/meminfo: memFree=839200/1048576 swapFree=0/0
[pid=16940] ppid=16939 vsize=2592 CPUtime=6.25
/proc/16940/stat : 16940 (aspuncud-user-1) S 16939 16940 2160 34817 2160 4202496 572 53259 0 41 0 0 603 22 18 0 1 0 58760871 2654208 298 1283457024 134512640 135304128 4288095040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16940/statm: 648 298 251 194 0 35 0
[pid=16949] ppid=16940 vsize=106020 CPUtime=283.78
/proc/16949/stat : 16949 (unclasp) R 16940 16940 2160 34817 2160 4202496 4523387 0 7 0 26442 1936 0 0 25 0 1 0 58760875 108564480 24723 1283457024 134512640 135121179 4286744448 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16949/statm: 26505 24723 321 149 0 25696 0
Current children cumulated CPU time (s) 290.03
Current children cumulated vsize (KiB) 108612

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.562
CPU time (s): 290.066
CPU user time (s): 270.473
CPU system time (s): 19.5932
CPU usage (%): 99.8293
Max. virtual memory (cumulated for all children) (KiB): 210336

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 270.473
system time used= 19.5932
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 4579604
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= 7293
involuntary context switches= 9293

runsolver used 0 second user time and 0 second system time

The end