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/201108251442/aspcud-paranoid-1.5/rand252.cudf.dudf-random.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-random//rand252.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand252.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.56 1.16 0.97 5/38 7708
/proc/meminfo: memFree=420548/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=0.01
/proc/7692/stat : 7692 (aspcud-paranoid) R 7691 7692 4778 34817 4778 4202496 625 2937 0 0 0 0 0 1 25 0 1 0 10199748 2658304 298 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/7692/statm: 649 298 250 194 0 36 0
[pid=7706] ppid=7692 vsize=2596 CPUtime=0
/proc/7706/stat : 7706 (aspcud-paranoid) R 7692 7692 4778 34817 4778 4202560 110 0 0 0 0 0 0 0 25 0 1 0 10199750 2658304 132 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0
/proc/7706/statm: 649 132 83 194 0 36 0
[pid=7707] ppid=7692 vsize=2596 CPUtime=0
/proc/7707/stat : 7707 (aspcud-paranoid) S 7692 7692 4778 34817 4778 4202560 110 0 0 0 0 0 0 0 25 0 1 0 10199750 2658304 132 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564457842 0 0 17 0 0 0 0
/proc/7707/statm: 649 132 83 194 0 36 0
[pid=7708] ppid=7692 vsize=2596 CPUtime=0
/proc/7708/stat : 7708 (aspcud-paranoid) R 7692 7692 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10199750 2658304 48 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/7708/statm: 649 48 0 194 0 36 0

[startup+0.168514 s]
/proc/loadavg: 1.56 1.16 0.97 5/38 7708
/proc/meminfo: memFree=420548/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=0.01
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 2937 0 0 0 0 0 1 25 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=1928 CPUtime=0
/proc/7706/stat : 7706 (clasp) S 7692 7692 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 10199750 1974272 159 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/7706/statm: 482 159 144 433 0 47 0
[pid=7707] ppid=7692 vsize=2584 CPUtime=0
/proc/7707/stat : 7707 (gringo) S 7692 7692 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10199750 2646016 272 1283457024 134512640 136933539 4292405232 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7707/statm: 646 272 242 592 0 51 0
[pid=7708] ppid=7692 vsize=4080 CPUtime=0.11
/proc/7708/stat : 7708 (cudf2lp) R 7692 7692 4778 34817 4778 4202496 970 0 0 0 10 1 0 0 25 0 1 0 10199750 4177920 793 1283457024 134512640 135786343 4290573888 18446744073709551615 134690176 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7708/statm: 1020 793 126 311 0 707 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 11188

[startup+0.21202 s]
/proc/loadavg: 1.56 1.16 0.97 5/38 7708
/proc/meminfo: memFree=420548/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=0.01
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 2937 0 0 0 0 0 1 25 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=1928 CPUtime=0
/proc/7706/stat : 7706 (clasp) S 7692 7692 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 10199750 1974272 159 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/7706/statm: 482 159 144 433 0 47 0
[pid=7707] ppid=7692 vsize=2584 CPUtime=0
/proc/7707/stat : 7707 (gringo) S 7692 7692 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10199750 2646016 272 1283457024 134512640 136933539 4292405232 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7707/statm: 646 272 242 592 0 51 0
[pid=7708] ppid=7692 vsize=5360 CPUtime=0.15
/proc/7708/stat : 7708 (cudf2lp) R 7692 7692 4778 34817 4778 4202496 1318 0 0 0 14 1 0 0 25 0 1 0 10199750 5488640 1052 1283457024 134512640 135786343 4290573888 18446744073709551615 134927696 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7708/statm: 1340 1052 126 311 0 1027 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 12468

[startup+0.300533 s]
/proc/loadavg: 1.56 1.16 0.97 5/38 7708
/proc/meminfo: memFree=420548/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=0.01
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 2937 0 0 0 0 0 1 25 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=1928 CPUtime=0
/proc/7706/stat : 7706 (clasp) S 7692 7692 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 10199750 1974272 159 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/7706/statm: 482 159 144 433 0 47 0
[pid=7707] ppid=7692 vsize=2584 CPUtime=0
/proc/7707/stat : 7707 (gringo) S 7692 7692 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10199750 2646016 272 1283457024 134512640 136933539 4292405232 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7707/statm: 646 272 242 592 0 51 0
[pid=7708] ppid=7692 vsize=7896 CPUtime=0.22
/proc/7708/stat : 7708 (cudf2lp) R 7692 7692 4778 34817 4778 4202496 1699 0 0 0 20 2 0 0 25 0 1 0 10199750 8085504 1433 1283457024 134512640 135786343 4290573888 18446744073709551615 135201719 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7708/statm: 1974 1433 126 311 0 1661 0
Current children cumulated CPU time (s) 0.23
Current children cumulated vsize (KiB) 15004

[startup+0.704538 s]
/proc/loadavg: 1.56 1.16 0.97 5/38 7708
/proc/meminfo: memFree=420548/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=0.01
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 2937 0 0 0 0 0 1 25 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=1928 CPUtime=0
/proc/7706/stat : 7706 (clasp) S 7692 7692 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 10199750 1974272 159 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/7706/statm: 482 159 144 433 0 47 0
[pid=7707] ppid=7692 vsize=2584 CPUtime=0
/proc/7707/stat : 7707 (gringo) S 7692 7692 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10199750 2646016 272 1283457024 134512640 136933539 4292405232 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7707/statm: 646 272 242 592 0 51 0
[pid=7708] ppid=7692 vsize=14528 CPUtime=0.59
/proc/7708/stat : 7708 (cudf2lp) R 7692 7692 4778 34817 4778 4202496 3946 0 0 0 54 5 0 0 25 0 1 0 10199750 14876672 3150 1283457024 134512640 135786343 4290573888 18446744073709551615 135200699 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7708/statm: 3632 3150 126 311 0 3319 0
Current children cumulated CPU time (s) 0.6
Current children cumulated vsize (KiB) 21636

[startup+1.5046 s]
/proc/loadavg: 1.56 1.16 0.97 2/39 7709
/proc/meminfo: memFree=381448/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=0.01
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 2937 0 0 0 0 0 1 25 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=1928 CPUtime=0
/proc/7706/stat : 7706 (clasp) S 7692 7692 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 10199750 1974272 159 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/7706/statm: 482 159 144 433 0 47 0
[pid=7707] ppid=7692 vsize=2584 CPUtime=0
/proc/7707/stat : 7707 (gringo) S 7692 7692 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10199750 2646016 272 1283457024 134512640 136933539 4292405232 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7707/statm: 646 272 242 592 0 51 0
[pid=7708] ppid=7692 vsize=25008 CPUtime=1.3
/proc/7708/stat : 7708 (cudf2lp) R 7692 7692 4778 34817 4778 4202496 7181 0 0 0 122 8 0 0 25 0 1 0 10199750 25608192 5583 1283457024 134512640 135786343 4290573888 18446744073709551615 134634056 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7708/statm: 6252 5583 126 311 0 5939 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 32116

[startup+3.10618 s]
/proc/loadavg: 1.56 1.16 0.97 2/39 7709
/proc/meminfo: memFree=348124/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=2.22
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 15888 0 0 0 0 208 14 18 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=14808 CPUtime=0.07
/proc/7706/stat : 7706 (clasp) R 7692 7692 4778 34817 4778 4202496 4089 0 0 0 5 2 0 0 18 0 1 0 10199750 15163392 3299 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7706/statm: 3702 3299 177 433 0 3267 0
[pid=7707] ppid=7692 vsize=23532 CPUtime=0.57
/proc/7707/stat : 7707 (gringo) R 7692 7692 4778 34817 4778 4202496 6500 0 0 0 56 1 0 0 18 0 1 0 10199750 24096768 4549 1283457024 134512640 136933539 4292405232 18446744073709551615 136204768 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7707/statm: 5883 4549 253 592 0 5288 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 40936

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

[startup+3.20619 s]
/proc/loadavg: 1.56 1.16 0.97 2/39 7709
/proc/meminfo: memFree=348124/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=2.22
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 15888 0 0 0 0 208 14 18 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=17584 CPUtime=0.11
/proc/7706/stat : 7706 (clasp) R 7692 7692 4778 34817 4778 4202496 4846 0 0 0 8 3 0 0 18 0 1 0 10199750 18006016 4056 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7706/statm: 4396 4056 177 433 0 3961 0
[pid=7707] ppid=7692 vsize=26188 CPUtime=0.63
/proc/7707/stat : 7707 (gringo) R 7692 7692 4778 34817 4778 4202496 7256 0 0 0 62 1 0 0 18 0 1 0 10199750 26816512 5305 1283457024 134512640 136933539 4292405232 18446744073709551615 134689637 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7707/statm: 6547 5305 253 592 0 5952 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 46368

[startup+3.6063 s]
/proc/loadavg: 1.56 1.16 0.97 3/38 7709
/proc/meminfo: memFree=352232/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=2.22
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 15888 0 0 0 0 208 14 18 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=25088 CPUtime=0.22
/proc/7706/stat : 7706 (clasp) R 7692 7692 4778 34817 4778 4202496 6698 0 0 0 19 3 0 0 18 0 1 0 10199750 25690112 5908 1283457024 134512640 136285277 4291005984 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7706/statm: 6272 5908 177 433 0 5837 0
[pid=7707] ppid=7692 vsize=29300 CPUtime=0.92
/proc/7707/stat : 7707 (gringo) R 7692 7692 4778 34817 4778 4202496 10317 0 0 0 90 2 0 0 18 0 1 0 10199750 30003200 6464 1283457024 134512640 136933539 4292405232 18446744073709551615 136175705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7707/statm: 7325 6464 254 592 0 6730 0
Current children cumulated CPU time (s) 3.36
Current children cumulated vsize (KiB) 56984

[startup+4.00641 s]
/proc/loadavg: 1.56 1.16 0.97 3/38 7709
/proc/meminfo: memFree=352232/1048576 swapFree=0/0
[pid=7692] ppid=7691 vsize=2596 CPUtime=3.16
/proc/7692/stat : 7692 (aspcud-paranoid) S 7691 7692 4778 34817 4778 4202496 650 26206 0 0 0 0 300 16 15 0 1 0 10199748 2658304 299 1283457024 134512640 135304128 4292394928 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7692/statm: 649 299 251 194 0 36 0
[pid=7706] ppid=7692 vsize=29916 CPUtime=0.6
/proc/7706/stat : 7706 (clasp) R 7692 7692 4778 34817 4778 4202496 8601 0 0 0 57 3 0 0 18 0 1 0 10199750 30633984 7239 1283457024 134512640 136285277 4291005984 18446744073709551615 134669568 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7706/statm: 7479 7239 233 433 0 7044 0
Current children cumulated CPU time (s) 3.76
Current children cumulated vsize (KiB) 32512

Child status: 0
Real time (s): 4.06965
CPU time (s): 3.83224
CPU user time (s): 3.61223
CPU system time (s): 0.220013
CPU usage (%): 94.1663
Max. virtual memory (cumulated for all children) (KiB): 65184

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.61223
system time used= 0.220013
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 39379
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= 1265
involuntary context switches= 1024

runsolver used 0 second user time and 0.008 second system time

The end