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/rand461.cudf.dudf-random.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-random//rand461.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand461.cudf.dudf-random.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.10 1.02 5/35 18369
/proc/meminfo: memFree=609920/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2588 CPUtime=0
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 4097182 2650112 280 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/18367/statm: 647 280 234 194 0 34 0
[pid=18368] ppid=18367 vsize=2588 CPUtime=0
/proc/18368/stat : 18368 (aspcud-trendy-1) R 18367 18367 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4097182 2650112 133 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18368/statm: 647 133 86 194 0 34 0
[pid=18369] ppid=18368 vsize=2588 CPUtime=0
/proc/18369/stat : 18369 (aspcud-trendy-1) R 18368 18367 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4097182 2650112 47 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18369/statm: 647 47 0 194 0 34 0

[startup+0.185542 s]
/proc/loadavg: 1.12 1.10 1.02 5/35 18369
/proc/meminfo: memFree=609920/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=0
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 624 2230 0 0 0 0 0 0 25 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205541 s]
/proc/loadavg: 1.12 1.10 1.02 5/35 18369
/proc/meminfo: memFree=609920/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=0
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 624 2230 0 0 0 0 0 0 25 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305571 s]
/proc/loadavg: 1.12 1.10 1.02 5/35 18369
/proc/meminfo: memFree=609920/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=0
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 624 2230 0 0 0 0 0 0 25 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.705672 s]
/proc/loadavg: 1.12 1.10 1.02 5/35 18369
/proc/meminfo: memFree=609920/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=0
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 624 2230 0 0 0 0 0 0 25 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50587 s]
/proc/loadavg: 1.11 1.10 1.02 2/39 18383
/proc/meminfo: memFree=587788/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=0
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 624 2230 0 0 0 0 0 0 25 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
[pid=18379] ppid=18367 vsize=1932 CPUtime=0
/proc/18379/stat : 18379 (clasp) S 18367 18367 1511 34817 1511 4202496 293 0 0 0 0 0 0 0 25 0 1 0 4097183 1978368 160 1283457024 134512640 136285277 4288545744 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/18379/statm: 483 160 144 433 0 48 0
[pid=18380] ppid=18367 vsize=2580 CPUtime=0
/proc/18380/stat : 18380 (gringo) S 18367 18367 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 4097183 2641920 271 1283457024 134512640 136933539 4294742576 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/18380/statm: 645 271 242 592 0 50 0
[pid=18381] ppid=18367 vsize=25008 CPUtime=1.49
/proc/18381/stat : 18381 (cudf2lp) R 18367 18367 1511 34817 1511 4202496 7237 0 0 0 144 5 0 0 25 0 1 0 4097183 25608192 5638 1283457024 134512640 135786343 4290401280 18446744073709551615 135199333 0 0 6 0 0 0 0 17 0 0 0 0
/proc/18381/statm: 6252 5638 126 311 0 5939 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 32116

[startup+3.1063 s]
/proc/loadavg: 1.11 1.10 1.02 3/39 18383
/proc/meminfo: memFree=568072/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=2.37
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 625 15137 0 0 0 0 229 8 18 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
[pid=18379] ppid=18367 vsize=16264 CPUtime=0.06
/proc/18379/stat : 18379 (clasp) R 18367 18367 1511 34817 1511 4202496 4474 0 0 0 5 1 0 0 18 0 1 0 4097183 16654336 3683 1283457024 134512640 136285277 4288545744 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18379/statm: 4066 3683 177 433 0 3631 0
[pid=18380] ppid=18367 vsize=25880 CPUtime=0.66
/proc/18380/stat : 18380 (gringo) R 18367 18367 1511 34817 1511 4202496 7205 0 0 0 66 0 0 0 18 0 1 0 4097183 26501120 5028 1283457024 134512640 136933539 4294742576 18446744073709551615 134687084 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18380/statm: 6470 5028 253 592 0 5875 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 44740

[startup+6.30724 s]
/proc/loadavg: 1.11 1.10 1.02 2/37 18383
/proc/meminfo: memFree=572692/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=3.72
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 625 29143 0 0 0 0 360 12 18 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
[pid=18379] ppid=18367 vsize=38452 CPUtime=2.59
/proc/18379/stat : 18379 (clasp) R 18367 18367 1511 34817 1511 4202496 11494 0 0 0 257 2 0 0 21 0 1 0 4097183 39374848 9354 1283457024 134512640 136285277 4288545744 18446744073709551615 134893073 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18379/statm: 9613 9354 234 433 0 9178 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 41048

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

[startup+6.40727 s]
/proc/loadavg: 1.11 1.10 1.02 2/37 18383
/proc/meminfo: memFree=572692/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=3.72
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 625 29143 0 0 0 0 360 12 18 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
[pid=18379] ppid=18367 vsize=38452 CPUtime=2.68
/proc/18379/stat : 18379 (clasp) R 18367 18367 1511 34817 1511 4202496 11494 0 0 0 266 2 0 0 22 0 1 0 4097183 39374848 9354 1283457024 134512640 136285277 4288545744 18446744073709551615 134893073 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18379/statm: 9613 9354 234 433 0 9178 0
Current children cumulated CPU time (s) 6.4
Current children cumulated vsize (KiB) 41048

[startup+6.80741 s]
/proc/loadavg: 1.10 1.10 1.02 2/37 18383
/proc/meminfo: memFree=572708/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=3.72
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 625 29143 0 0 0 0 360 12 18 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
[pid=18379] ppid=18367 vsize=38452 CPUtime=3.08
/proc/18379/stat : 18379 (clasp) R 18367 18367 1511 34817 1511 4202496 11494 0 0 0 306 2 0 0 23 0 1 0 4097183 39374848 9354 1283457024 134512640 136285277 4288545744 18446744073709551615 134960178 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18379/statm: 9613 9354 234 433 0 9178 0
Current children cumulated CPU time (s) 6.8
Current children cumulated vsize (KiB) 41048

[startup+7.00748 s]
/proc/loadavg: 1.10 1.10 1.02 2/37 18383
/proc/meminfo: memFree=572708/1048576 swapFree=0/0
[pid=18367] ppid=18366 vsize=2596 CPUtime=3.72
/proc/18367/stat : 18367 (aspcud-trendy-1) S 18366 18367 1511 34817 1511 4202496 625 29143 0 0 0 0 360 12 18 0 1 0 4097182 2658304 299 1283457024 134512640 135304128 4292753424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18367/statm: 649 299 251 194 0 36 0
[pid=18379] ppid=18367 vsize=38452 CPUtime=3.28
/proc/18379/stat : 18379 (clasp) R 18367 18367 1511 34817 1511 4202496 11494 0 0 0 326 2 0 0 25 0 1 0 4097183 39374848 9354 1283457024 134512640 136285277 4288545744 18446744073709551615 134930797 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18379/statm: 9613 9354 234 433 0 9178 0
Current children cumulated CPU time (s) 7
Current children cumulated vsize (KiB) 41048

Child status: 0
Real time (s): 7.07995
CPU time (s): 7.08044
CPU user time (s): 6.90843
CPU system time (s): 0.17201
CPU usage (%): 100.007
Max. virtual memory (cumulated for all children) (KiB): 88140

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.90843
system time used= 0.17201
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 45253
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= 1582
involuntary context switches= 1217

runsolver used 0 second user time and 0 second system time

The end