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/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/ff4a1d84-d490-11df-9e6c-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.23 1.25 1.15 5/36 3150
/proc/meminfo: memFree=262120/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2588 CPUtime=0
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 5231783 2650112 280 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/3148/statm: 647 280 234 194 0 34 0
[pid=3149] ppid=3148 vsize=2588 CPUtime=0
/proc/3149/stat : 3149 (aspcud-trendy-1) R 3148 3148 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 5231783 2650112 133 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3149/statm: 647 133 86 194 0 34 0
[pid=3150] ppid=3149 vsize=2588 CPUtime=0
/proc/3150/stat : 3150 (aspcud-trendy-1) R 3149 3148 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 5231783 2650112 47 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3150/statm: 647 47 0 194 0 34 0

[startup+0.115229 s]
/proc/loadavg: 1.23 1.25 1.15 5/36 3150
/proc/meminfo: memFree=262120/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=0
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 625 2232 0 0 0 0 0 0 25 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.20524 s]
/proc/loadavg: 1.23 1.25 1.15 5/36 3150
/proc/meminfo: memFree=262120/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=0
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 625 2232 0 0 0 0 0 0 25 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305251 s]
/proc/loadavg: 1.23 1.25 1.15 5/36 3150
/proc/meminfo: memFree=262120/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=0
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 625 2232 0 0 0 0 0 0 25 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.705298 s]
/proc/loadavg: 1.23 1.25 1.15 5/36 3150
/proc/meminfo: memFree=262120/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=0
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 625 2232 0 0 0 0 0 0 25 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50548 s]
/proc/loadavg: 1.21 1.24 1.15 2/38 3162
/proc/meminfo: memFree=239640/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=0
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 625 2232 0 0 0 0 0 0 25 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
[pid=3160] ppid=3148 vsize=1928 CPUtime=0
/proc/3160/stat : 3160 (clasp) S 3148 3148 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 5231784 1974272 159 1283457024 134512640 136285277 4289133648 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/3160/statm: 482 159 144 433 0 47 0
[pid=3161] ppid=3148 vsize=2584 CPUtime=0
/proc/3161/stat : 3161 (gringo) S 3148 3148 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 5231784 2646016 272 1283457024 134512640 136933539 4293343440 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3161/statm: 646 272 242 592 0 51 0
[pid=3162] ppid=3148 vsize=36756 CPUtime=1.49
/proc/3162/stat : 3162 (cudf2lp) R 3148 3148 1511 34817 1511 4202496 10462 0 0 0 144 5 0 0 25 0 1 0 5231784 37638144 8718 1283457024 134512640 135786343 4289924528 18446744073709551615 135201719 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3162/statm: 9189 8718 133 311 0 8876 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 43864

[startup+3.10596 s]
/proc/loadavg: 1.21 1.24 1.15 3/38 3162
/proc/meminfo: memFree=208020/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=1.85
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 626 14228 0 0 0 0 176 9 18 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
[pid=3160] ppid=3148 vsize=25804 CPUtime=0.16
/proc/3160/stat : 3160 (clasp) R 3148 3148 1511 34817 1511 4202496 7196 0 0 0 14 2 0 0 18 0 1 0 5231784 26423296 6000 1283457024 134512640 136285277 4289133648 18446744073709551615 134782897 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3160/statm: 6451 6000 177 433 0 6016 0
[pid=3161] ppid=3148 vsize=47664 CPUtime=1.07
/proc/3161/stat : 3161 (gringo) R 3148 3148 1511 34817 1511 4202496 12491 0 0 0 101 6 0 0 18 0 1 0 5231784 48807936 8646 1283457024 134512640 136933539 4293343440 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3161/statm: 11916 8646 253 592 0 11321 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 76064

[startup+6.307 s]
/proc/loadavg: 1.20 1.24 1.15 2/36 3162
/proc/meminfo: memFree=224560/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=3.12
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 626 28373 0 0 0 0 295 17 18 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
[pid=3160] ppid=3148 vsize=38876 CPUtime=3.17
/proc/3160/stat : 3160 (clasp) R 3148 3148 1511 34817 1511 4202496 11495 0 0 0 312 5 0 0 25 0 1 0 5231784 39809024 9462 1283457024 134512640 136285277 4289133648 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3160/statm: 9719 9462 234 433 0 9284 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 41472

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

[startup+6.40701 s]
/proc/loadavg: 1.20 1.24 1.15 2/36 3162
/proc/meminfo: memFree=224560/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=3.12
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 626 28373 0 0 0 0 295 17 18 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
[pid=3160] ppid=3148 vsize=38876 CPUtime=3.27
/proc/3160/stat : 3160 (clasp) R 3148 3148 1511 34817 1511 4202496 11495 0 0 0 322 5 0 0 25 0 1 0 5231784 39809024 9462 1283457024 134512640 136285277 4289133648 18446744073709551615 134930706 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3160/statm: 9719 9462 234 433 0 9284 0
Current children cumulated CPU time (s) 6.39
Current children cumulated vsize (KiB) 41472

[startup+6.60704 s]
/proc/loadavg: 1.20 1.24 1.15 2/36 3162
/proc/meminfo: memFree=224560/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=3.12
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 626 28373 0 0 0 0 295 17 18 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
[pid=3160] ppid=3148 vsize=38876 CPUtime=3.47
/proc/3160/stat : 3160 (clasp) R 3148 3148 1511 34817 1511 4202496 11495 0 0 0 342 5 0 0 25 0 1 0 5231784 39809024 9462 1283457024 134512640 136285277 4289133648 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3160/statm: 9719 9462 234 433 0 9284 0
Current children cumulated CPU time (s) 6.59
Current children cumulated vsize (KiB) 41472

[startup+6.70705 s]
/proc/loadavg: 1.20 1.24 1.15 2/36 3162
/proc/meminfo: memFree=224560/1048576 swapFree=0/0
[pid=3148] ppid=3147 vsize=2596 CPUtime=3.12
/proc/3148/stat : 3148 (aspcud-trendy-1) S 3147 3148 1511 34817 1511 4202496 626 28373 0 0 0 0 295 17 18 0 1 0 5231783 2658304 299 1283457024 134512640 135304128 4294767040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3148/statm: 649 299 251 194 0 36 0
[pid=3160] ppid=3148 vsize=32940 CPUtime=3.57
/proc/3160/stat : 3160 (clasp) R 3148 3148 1511 34817 1511 4202496 11503 0 0 0 352 5 0 0 25 0 1 0 5231784 33730560 7986 1283457024 134512640 136285277 4289133648 18446744073709551615 135635426 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3160/statm: 8235 7986 242 433 0 7800 0
Current children cumulated CPU time (s) 6.69
Current children cumulated vsize (KiB) 35536

Child status: 0
Real time (s): 6.74826
CPU time (s): 6.74442
CPU user time (s): 6.50441
CPU system time (s): 0.240015
CPU usage (%): 99.9432
Max. virtual memory (cumulated for all children) (KiB): 83264

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.50441
system time used= 0.240015
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44471
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= 1540
involuntary context switches= 1173

runsolver used 0 second user time and 0 second system time

The end