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/201012070034/aspcud-trendy-1.3/randa651ed.cudf.difficult.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/difficult//randa651ed.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/randa651ed.cudf.difficult.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.02 1.02 1.00 1/40 3337
/proc/meminfo: memFree=921176/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=3024 CPUtime=0
/proc/3337/stat : 3337 (runsolver) D 3336 3337 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 885135786 3096576 94 1283457024 134512640 134586868 4286566752 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/3337/statm: 756 94 62 19 0 54 0

[startup+0.18807 s]
/proc/loadavg: 1.02 1.02 1.00 1/40 3337
/proc/meminfo: memFree=921176/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=0
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 2218 0 3 0 0 0 0 25 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.204108 s]
/proc/loadavg: 1.02 1.02 1.00 1/40 3337
/proc/meminfo: memFree=921176/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=0
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 2218 0 3 0 0 0 0 25 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.311175 s]
/proc/loadavg: 1.02 1.02 1.00 1/40 3337
/proc/meminfo: memFree=921176/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=0
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 2218 0 3 0 0 0 0 25 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.711246 s]
/proc/loadavg: 1.02 1.02 1.00 1/40 3337
/proc/meminfo: memFree=921176/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=0
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 2218 0 3 0 0 0 0 25 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.5114 s]
/proc/loadavg: 1.10 1.04 1.01 2/44 3351
/proc/meminfo: memFree=882412/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=0.86
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 11422 0 19 0 0 82 4 18 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=10508 CPUtime=0.05
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 2786 0 18 0 5 0 0 0 18 0 1 0 885135790 10760192 2285 1283457024 134512640 136223643 4289041472 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 2627 2285 174 418 0 2207 0
[pid=3350] ppid=3337 vsize=16228 CPUtime=0.34
/proc/3350/stat : 3350 (gringo) R 3337 3337 4159 34819 4229 4202496 4069 0 22 0 34 0 0 0 18 0 1 0 885135790 16617472 3202 1283457024 134512640 136959103 4290318320 18446744073709551615 134699204 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3350/statm: 4057 3202 256 598 0 3456 0
Current children cumulated CPU time (s) 1.25
Current children cumulated vsize (KiB) 29332

[startup+3.11184 s]
/proc/loadavg: 1.10 1.04 1.01 2/42 3351
/proc/meminfo: memFree=895716/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=22744 CPUtime=1.33
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 6057 0 19 0 133 0 0 0 19 0 1 0 885135790 23289856 5141 1283457024 134512640 136223643 4289041472 18446744073709551615 134922640 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 5686 5141 225 418 0 5266 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 25340

[startup+6.31252 s]
/proc/loadavg: 1.09 1.04 1.00 2/42 3351
/proc/meminfo: memFree=888656/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=33492 CPUtime=4.53
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 8781 0 19 0 452 1 0 0 25 0 1 0 885135790 34295808 7865 1283457024 134512640 136223643 4289041472 18446744073709551615 134711295 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 8373 7865 225 418 0 7953 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 36088

[startup+12.7139 s]
/proc/loadavg: 1.08 1.04 1.00 2/42 3351
/proc/meminfo: memFree=882828/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=38112 CPUtime=10.92
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 9934 0 19 0 1090 2 0 0 25 0 1 0 885135790 39026688 9018 1283457024 134512640 136223643 4289041472 18446744073709551615 134917872 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 9528 9018 225 418 0 9108 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 40708

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

[startup+12.814 s]
/proc/loadavg: 1.08 1.04 1.00 2/42 3351
/proc/meminfo: memFree=882828/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=38376 CPUtime=11.02
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 9976 0 19 0 1100 2 0 0 25 0 1 0 885135790 39297024 9060 1283457024 134512640 136223643 4289041472 18446744073709551615 134931416 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 9594 9060 225 418 0 9174 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 40972

[startup+16.0147 s]
/proc/loadavg: 1.07 1.03 1.00 2/42 3351
/proc/meminfo: memFree=878240/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=41016 CPUtime=14.22
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 10655 0 19 0 1420 2 0 0 25 0 1 0 885135790 42000384 9739 1283457024 134512640 136223643 4289041472 18446744073709551615 134930945 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 10254 9739 225 418 0 9834 0
Current children cumulated CPU time (s) 15.75
Current children cumulated vsize (KiB) 43612

[startup+19.2056 s]
/proc/loadavg: 1.07 1.03 1.00 2/42 3351
/proc/meminfo: memFree=874892/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=43920 CPUtime=17.41
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 11376 0 19 0 1739 2 0 0 25 0 1 0 885135790 44974080 10460 1283457024 134512640 136223643 4289041472 18446744073709551615 134917906 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 10980 10460 225 418 0 10560 0
Current children cumulated CPU time (s) 18.94
Current children cumulated vsize (KiB) 46516

[startup+20.8059 s]
/proc/loadavg: 1.07 1.03 1.00 2/42 3351
/proc/meminfo: memFree=874892/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=43920 CPUtime=19
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 11377 0 19 0 1898 2 0 0 25 0 1 0 885135790 44974080 10461 1283457024 134512640 136223643 4289041472 18446744073709551615 134631470 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 10980 10461 225 418 0 10560 0
Current children cumulated CPU time (s) 20.53
Current children cumulated vsize (KiB) 46516

[startup+21.206 s]
/proc/loadavg: 1.07 1.03 1.00 2/42 3351
/proc/meminfo: memFree=874892/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=43920 CPUtime=19.4
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 11377 0 19 0 1938 2 0 0 25 0 1 0 885135790 44974080 10461 1283457024 134512640 136223643 4289041472 18446744073709551615 134931115 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 10980 10461 225 418 0 10560 0
Current children cumulated CPU time (s) 20.93
Current children cumulated vsize (KiB) 46516

[startup+21.406 s]
/proc/loadavg: 1.07 1.03 1.00 2/42 3351
/proc/meminfo: memFree=874892/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=1.53
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 623 18390 0 41 0 0 146 7 15 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
[pid=3349] ppid=3337 vsize=43920 CPUtime=19.6
/proc/3349/stat : 3349 (clasp) R 3337 3337 4159 34819 4229 4202496 11377 0 19 0 1958 2 0 0 25 0 1 0 885135790 44974080 10461 1283457024 134512640 136223643 4289041472 18446744073709551615 134929407 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3349/statm: 10980 10461 225 418 0 10560 0
Current children cumulated CPU time (s) 21.13
Current children cumulated vsize (KiB) 46516

[startup+21.5054 s]
/proc/loadavg: 1.07 1.03 1.00 2/42 3351
/proc/meminfo: memFree=874892/1048576 swapFree=2080268/2097144
[pid=3337] ppid=3336 vsize=2596 CPUtime=21.22
/proc/3337/stat : 3337 (aspcud-trendy-1) S 3336 3337 4159 34819 4229 4202496 639 29775 0 60 0 0 2112 10 18 0 1 0 885135786 2658304 300 1283457024 134512640 135304128 4288908384 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/3337/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 21.22
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 21.5509
CPU time (s): 21.2453
CPU user time (s): 21.1293
CPU system time (s): 0.116007
CPU usage (%): 98.5823
Max. virtual memory (cumulated for all children) (KiB): 48372

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 21.1293
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= 34010
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= 796
involuntary context switches= 747

runsolver used 0 second user time and 0 second system time

The end