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/rand144.cudf.s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s/rand144.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand144.cudf.s.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.07 1.03 1.00 5/37 4893
/proc/meminfo: memFree=568644/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2588 CPUtime=0
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 1289543 2650112 280 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/4891/statm: 647 280 234 194 0 34 0
[pid=4892] ppid=4891 vsize=2588 CPUtime=0
/proc/4892/stat : 4892 (aspcud-trendy-1) R 4891 4891 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 1289543 2650112 133 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/4892/statm: 647 133 86 194 0 34 0
[pid=4893] ppid=4892 vsize=2588 CPUtime=0
/proc/4893/stat : 4893 (aspcud-trendy-1) R 4892 4891 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1289543 2650112 47 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/4893/statm: 647 47 0 194 0 34 0

[startup+0.145334 s]
/proc/loadavg: 1.07 1.03 1.00 5/37 4893
/proc/meminfo: memFree=568644/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.01
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.205358 s]
/proc/loadavg: 1.07 1.03 1.00 5/37 4893
/proc/meminfo: memFree=568644/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.01
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.305368 s]
/proc/loadavg: 1.07 1.03 1.00 5/37 4893
/proc/meminfo: memFree=568644/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.01
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.705455 s]
/proc/loadavg: 1.07 1.03 1.00 5/37 4893
/proc/meminfo: memFree=568644/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.4
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 5417 0 0 0 0 37 3 21 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 2596

[startup+1.50572 s]
/proc/loadavg: 1.14 1.04 1.01 2/37 4905
/proc/meminfo: memFree=560208/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=9836 CPUtime=0.83
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 2723 0 0 0 82 1 0 0 20 0 1 0 1289544 10072064 2242 1283457024 134512640 136285277 4293865696 18446744073709551615 134733791 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2459 2242 234 433 0 2024 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 12432

[startup+3.10606 s]
/proc/loadavg: 1.14 1.04 1.01 2/37 4905
/proc/meminfo: memFree=560208/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=9836 CPUtime=2.43
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 2727 0 0 0 242 1 0 0 25 0 1 0 1289544 10072064 2246 1283457024 134512640 136285277 4293865696 18446744073709551615 134615146 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2459 2246 234 433 0 2024 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 12432

[startup+6.30666 s]
/proc/loadavg: 1.13 1.04 1.01 2/37 4905
/proc/meminfo: memFree=560208/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11068 CPUtime=5.62
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3014 0 0 0 559 3 0 0 25 0 1 0 1289544 11333632 2533 1283457024 134512640 136285277 4293865696 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2767 2533 234 433 0 2332 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 13664

[startup+12.7077 s]
/proc/loadavg: 1.12 1.04 1.01 2/37 4906
/proc/meminfo: memFree=559356/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11200 CPUtime=12.02
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3067 0 0 0 1199 3 0 0 25 0 1 0 1289544 11468800 2586 1283457024 134512640 136285277 4293865696 18446744073709551615 134964945 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2800 2586 234 433 0 2365 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 13796

[startup+25.5106 s]
/proc/loadavg: 1.10 1.04 1.01 2/37 4907
/proc/meminfo: memFree=559108/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11332 CPUtime=24.81
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3099 0 0 0 2478 3 0 0 25 0 1 0 1289544 11603968 2618 1283457024 134512640 136285277 4293865696 18446744073709551615 134615008 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2833 2618 234 433 0 2398 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 13928

[startup+51.106 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 4910
/proc/meminfo: memFree=558736/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11728 CPUtime=50.38
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3196 0 0 0 5035 3 0 0 25 0 1 0 1289544 12009472 2715 1283457024 134512640 136285277 4293865696 18446744073709551615 134733720 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2932 2715 234 433 0 2497 0
Current children cumulated CPU time (s) 51.05
Current children cumulated vsize (KiB) 14324

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

[startup+51.206 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 4910
/proc/meminfo: memFree=558736/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11728 CPUtime=50.48
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3196 0 0 0 5045 3 0 0 25 0 1 0 1289544 12009472 2715 1283457024 134512640 136285277 4293865696 18446744073709551615 134723341 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2932 2715 234 433 0 2497 0
Current children cumulated CPU time (s) 51.15
Current children cumulated vsize (KiB) 14324

[startup+64.0084 s]
/proc/loadavg: 1.05 1.03 1.00 2/37 4911
/proc/meminfo: memFree=558488/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11860 CPUtime=63.27
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3238 0 0 0 6324 3 0 0 25 0 1 0 1289544 12144640 2757 1283457024 134512640 136285277 4293865696 18446744073709551615 134615112 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2965 2757 234 433 0 2530 0
Current children cumulated CPU time (s) 63.94
Current children cumulated vsize (KiB) 14456

[startup+70.41 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 4912
/proc/meminfo: memFree=558488/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11860 CPUtime=69.67
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3238 0 0 0 6964 3 0 0 25 0 1 0 1289544 12144640 2757 1283457024 134512640 136285277 4293865696 18446744073709551615 134960181 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2965 2757 234 433 0 2530 0
Current children cumulated CPU time (s) 70.34
Current children cumulated vsize (KiB) 14456

[startup+72.0103 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 4912
/proc/meminfo: memFree=558488/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11860 CPUtime=71.27
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3238 0 0 0 7124 3 0 0 25 0 1 0 1289544 12144640 2757 1283457024 134512640 136285277 4293865696 18446744073709551615 134931352 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2965 2757 234 433 0 2530 0
Current children cumulated CPU time (s) 71.94
Current children cumulated vsize (KiB) 14456

[startup+73.6118 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 4912
/proc/meminfo: memFree=558488/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11992 CPUtime=72.88
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3247 0 0 0 7285 3 0 0 25 0 1 0 1289544 12279808 2766 1283457024 134512640 136285277 4293865696 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2998 2766 234 433 0 2563 0
Current children cumulated CPU time (s) 73.55
Current children cumulated vsize (KiB) 14588

[startup+74.0118 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 4912
/proc/meminfo: memFree=558488/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11992 CPUtime=73.28
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3262 0 0 0 7325 3 0 0 25 0 1 0 1289544 12279808 2781 1283457024 134512640 136285277 4293865696 18446744073709551615 134959506 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2998 2781 234 433 0 2563 0
Current children cumulated CPU time (s) 73.95
Current children cumulated vsize (KiB) 14588

[startup+74.2119 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 4912
/proc/meminfo: memFree=558488/1048576 swapFree=0/0
[pid=4891] ppid=4890 vsize=2596 CPUtime=0.67
/proc/4891/stat : 4891 (aspcud-trendy-1) S 4890 4891 1511 34817 1511 4202496 625 8850 0 0 0 0 64 3 19 0 1 0 1289543 2658304 299 1283457024 134512640 135304128 4290905680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4891/statm: 649 299 251 194 0 36 0
[pid=4903] ppid=4891 vsize=11992 CPUtime=73.48
/proc/4903/stat : 4903 (clasp) R 4891 4891 1511 34817 1511 4202496 3262 0 0 0 7345 3 0 0 25 0 1 0 1289544 12279808 2781 1283457024 134512640 136285277 4293865696 18446744073709551615 134649414 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4903/statm: 2998 2781 234 433 0 2563 0
Current children cumulated CPU time (s) 74.15
Current children cumulated vsize (KiB) 14588

Child status: 0
Real time (s): 74.2456
CPU time (s): 74.1926
CPU user time (s): 74.0966
CPU system time (s): 0.096006
CPU usage (%): 99.9287
Max. virtual memory (cumulated for all children) (KiB): 14588

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 74.0966
system time used= 0.096006
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 16405
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= 541
involuntary context switches= 1390

runsolver used 0 second user time and 0 second system time

The end