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/201108241238/aspcud-trendy-1.5/27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf.dudf-real.result 

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.12 1.06 1.01 5/37 11153
/proc/meminfo: memFree=586668/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2592 CPUtime=0
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 2576238 2654208 280 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/11151/statm: 648 280 234 194 0 35 0
[pid=11152] ppid=11151 vsize=2592 CPUtime=0
/proc/11152/stat : 11152 (aspcud-trendy-1) R 11151 11151 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2576238 2654208 133 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/11152/statm: 648 133 86 194 0 35 0
[pid=11153] ppid=11152 vsize=2592 CPUtime=0
/proc/11153/stat : 11153 (aspcud-trendy-1) R 11152 11151 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2576238 2654208 47 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/11153/statm: 648 47 0 194 0 35 0

[startup+0.185259 s]
/proc/loadavg: 1.12 1.06 1.01 5/37 11153
/proc/meminfo: memFree=586668/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=0.01
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 623 2226 0 0 0 0 0 1 25 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.205254 s]
/proc/loadavg: 1.12 1.06 1.01 5/37 11153
/proc/meminfo: memFree=586668/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=0.01
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 623 2226 0 0 0 0 0 1 25 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.305271 s]
/proc/loadavg: 1.12 1.06 1.01 5/37 11153
/proc/meminfo: memFree=586668/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=0.01
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 623 2226 0 0 0 0 0 1 25 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.705321 s]
/proc/loadavg: 1.12 1.06 1.01 5/37 11153
/proc/meminfo: memFree=586668/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=0.01
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 623 2226 0 0 0 0 0 1 25 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.50543 s]
/proc/loadavg: 1.12 1.06 1.01 2/39 11165
/proc/meminfo: memFree=563940/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=0.01
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 623 2226 0 0 0 0 0 1 25 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
[pid=11163] ppid=11151 vsize=1932 CPUtime=0
/proc/11163/stat : 11163 (clasp) S 11151 11151 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 2576239 1978368 160 1283457024 134512640 136285277 4292286304 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/11163/statm: 483 160 144 433 0 48 0
[pid=11164] ppid=11151 vsize=2580 CPUtime=0
/proc/11164/stat : 11164 (gringo) S 11151 11151 1511 34817 1511 4202496 403 0 0 0 0 0 0 0 25 0 1 0 2576239 2641920 271 1283457024 134512640 136933539 4293406944 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11164/statm: 645 271 242 592 0 50 0
[pid=11165] ppid=11151 vsize=34864 CPUtime=1.49
/proc/11165/stat : 11165 (cudf2lp) R 11151 11151 1511 34817 1511 4202496 10012 0 0 0 142 7 0 0 25 0 1 0 2576239 35700736 8268 1283457024 134512640 135786343 4291604288 18446744073709551615 134548267 0 0 6 0 0 0 0 17 0 0 0 0
/proc/11165/statm: 8716 8268 133 311 0 8403 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 41976

[startup+3.10562 s]
/proc/loadavg: 1.12 1.06 1.01 3/39 11165
/proc/meminfo: memFree=533684/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=1.88
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 624 14455 0 0 0 0 178 10 18 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
[pid=11163] ppid=11151 vsize=25820 CPUtime=0.14
/proc/11163/stat : 11163 (clasp) R 11151 11151 1511 34817 1511 4202496 7232 0 0 0 12 2 0 0 18 0 1 0 2576239 26439680 6036 1283457024 134512640 136285277 4292286304 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11163/statm: 6455 6036 177 433 0 6020 0
[pid=11164] ppid=11151 vsize=43720 CPUtime=1.06
/proc/11164/stat : 11164 (gringo) R 11151 11151 1511 34817 1511 4202496 12168 0 0 0 104 2 0 0 18 0 1 0 2576239 44769280 8403 1283457024 134512640 136933539 4293406944 18446744073709551615 135827760 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11164/statm: 10930 8403 253 592 0 10335 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 72140

[startup+6.30668 s]
/proc/loadavg: 1.11 1.06 1.01 2/37 11165
/proc/meminfo: memFree=544016/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=3.32
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 624 29554 0 0 0 0 318 14 18 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
[pid=11163] ppid=11151 vsize=43840 CPUtime=2.97
/proc/11163/stat : 11163 (clasp) R 11151 11151 1511 34817 1511 4202496 13140 0 0 0 294 3 0 0 23 0 1 0 2576239 44892160 10701 1283457024 134512640 136285277 4292286304 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11163/statm: 10960 10701 234 433 0 10525 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 46440

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

[startup+6.40671 s]
/proc/loadavg: 1.11 1.06 1.01 2/37 11165
/proc/meminfo: memFree=544016/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=3.32
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 624 29554 0 0 0 0 318 14 18 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
[pid=11163] ppid=11151 vsize=43840 CPUtime=3.07
/proc/11163/stat : 11163 (clasp) R 11151 11151 1511 34817 1511 4202496 13140 0 0 0 304 3 0 0 23 0 1 0 2576239 44892160 10701 1283457024 134512640 136285277 4292286304 18446744073709551615 134893019 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11163/statm: 10960 10701 234 433 0 10525 0
Current children cumulated CPU time (s) 6.39
Current children cumulated vsize (KiB) 46440

[startup+8.00741 s]
/proc/loadavg: 1.11 1.06 1.01 2/37 11166
/proc/meminfo: memFree=544140/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=3.32
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 624 29554 0 0 0 0 318 14 18 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
[pid=11163] ppid=11151 vsize=43840 CPUtime=4.67
/proc/11163/stat : 11163 (clasp) R 11151 11151 1511 34817 1511 4202496 13140 0 0 0 464 3 0 0 25 0 1 0 2576239 44892160 10701 1283457024 134512640 136285277 4292286304 18446744073709551615 134930797 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11163/statm: 10960 10701 234 433 0 10525 0
Current children cumulated CPU time (s) 7.99
Current children cumulated vsize (KiB) 46440

[startup+8.40758 s]
/proc/loadavg: 1.11 1.06 1.01 2/37 11166
/proc/meminfo: memFree=544140/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=3.32
/proc/11151/stat : 11151 (aspcud-trendy-1) S 11150 11151 1511 34817 1511 4202496 624 29554 0 0 0 0 318 14 18 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
[pid=11163] ppid=11151 vsize=43840 CPUtime=5.07
/proc/11163/stat : 11163 (clasp) R 11151 11151 1511 34817 1511 4202496 13140 0 0 0 504 3 0 0 25 0 1 0 2576239 44892160 10701 1283457024 134512640 136285277 4292286304 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11163/statm: 10960 10701 234 433 0 10525 0
Current children cumulated CPU time (s) 8.39
Current children cumulated vsize (KiB) 46440

[startup+8.60766 s]
/proc/loadavg: 1.11 1.06 1.01 2/37 11166
/proc/meminfo: memFree=544140/1048576 swapFree=0/0
[pid=11151] ppid=11150 vsize=2600 CPUtime=8.6
/proc/11151/stat : 11151 (aspcud-trendy-1) R 11150 11151 1511 34817 1511 4202496 625 42703 0 0 0 0 842 18 18 0 1 0 2576238 2662400 299 1283457024 134512640 135304128 4286865984 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/11151/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 8.6
Current children cumulated vsize (KiB) 2600

Child status: 0
Real time (s): 8.63457
CPU time (s): 8.63254
CPU user time (s): 8.44053
CPU system time (s): 0.192012
CPU usage (%): 99.9764
Max. virtual memory (cumulated for all children) (KiB): 91264

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.44053
system time used= 0.192012
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 47289
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1909
involuntary context switches= 1517

runsolver used 0 second user time and 0 second system time

The end