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/rand885.cudf.s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s/rand885.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand885.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.03 1.03 1.00 5/35 19814
/proc/meminfo: memFree=514364/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2592 CPUtime=0
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 4576081 2654208 280 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/19812/statm: 648 280 234 194 0 35 0
[pid=19813] ppid=19812 vsize=2592 CPUtime=0
/proc/19813/stat : 19813 (aspcud-trendy-1) R 19812 19812 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4576081 2654208 133 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/19813/statm: 648 133 86 194 0 35 0
[pid=19814] ppid=19813 vsize=2592 CPUtime=0
/proc/19814/stat : 19814 (aspcud-trendy-1) R 19813 19812 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4576082 2654208 47 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/19814/statm: 648 47 0 194 0 35 0

[startup+0.155754 s]
/proc/loadavg: 1.03 1.03 1.00 5/35 19814
/proc/meminfo: memFree=514364/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 625 2226 0 0 0 0 0 0 25 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.205764 s]
/proc/loadavg: 1.03 1.03 1.00 5/35 19814
/proc/meminfo: memFree=514364/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 625 2226 0 0 0 0 0 0 25 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.305772 s]
/proc/loadavg: 1.03 1.03 1.00 5/35 19814
/proc/meminfo: memFree=514364/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 625 2226 0 0 0 0 0 0 25 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.705831 s]
/proc/loadavg: 1.03 1.03 1.00 5/35 19814
/proc/meminfo: memFree=514364/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.38
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 5419 0 0 0 0 36 2 21 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.38
Current children cumulated vsize (KiB) 2600

[startup+1.506 s]
/proc/loadavg: 1.03 1.03 1.00 2/35 19826
/proc/meminfo: memFree=506052/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=9888 CPUtime=0.82
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2714 0 0 0 80 2 0 0 20 0 1 0 4576083 10125312 2242 1283457024 134512640 136285277 4290397584 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2472 2242 234 433 0 2037 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 12488

[startup+3.10625 s]
/proc/loadavg: 1.02 1.03 1.00 2/35 19826
/proc/meminfo: memFree=506052/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=9888 CPUtime=2.42
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2714 0 0 0 240 2 0 0 25 0 1 0 4576083 10125312 2242 1283457024 134512640 136285277 4290397584 18446744073709551615 134930666 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2472 2242 234 433 0 2037 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 12488

[startup+6.30676 s]
/proc/loadavg: 1.02 1.03 1.00 2/35 19826
/proc/meminfo: memFree=506068/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10020 CPUtime=5.62
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2764 0 0 0 560 2 0 0 25 0 1 0 4576083 10260480 2292 1283457024 134512640 136285277 4290397584 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2505 2292 234 433 0 2070 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 12620

[startup+12.7077 s]
/proc/loadavg: 1.02 1.03 1.00 2/35 19826
/proc/meminfo: memFree=505944/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10284 CPUtime=12.03
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2835 0 0 0 1201 2 0 0 25 0 1 0 4576083 10530816 2363 1283457024 134512640 136285277 4290397584 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2571 2363 234 433 0 2136 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 12884

[startup+25.5101 s]
/proc/loadavg: 1.02 1.03 1.00 2/37 19828
/proc/meminfo: memFree=505548/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10548 CPUtime=24.82
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2897 0 0 0 2480 2 0 0 25 0 1 0 4576083 10801152 2425 1283457024 134512640 136285277 4290397584 18446744073709551615 134735675 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2637 2425 234 433 0 2202 0
Current children cumulated CPU time (s) 25.49
Current children cumulated vsize (KiB) 13148

[startup+51.1075 s]
/proc/loadavg: 1.01 1.03 1.00 2/37 19830
/proc/meminfo: memFree=505300/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10680 CPUtime=50.4
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2933 0 0 0 5037 3 0 0 25 0 1 0 4576083 10936320 2461 1283457024 134512640 136285277 4290397584 18446744073709551615 134723294 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2670 2461 234 433 0 2235 0
Current children cumulated CPU time (s) 51.07
Current children cumulated vsize (KiB) 13280

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

[startup+51.2075 s]
/proc/loadavg: 1.01 1.03 1.00 2/37 19830
/proc/meminfo: memFree=505300/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10680 CPUtime=50.5
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2933 0 0 0 5047 3 0 0 25 0 1 0 4576083 10936320 2461 1283457024 134512640 136285277 4290397584 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2670 2461 234 433 0 2235 0
Current children cumulated CPU time (s) 51.17
Current children cumulated vsize (KiB) 13280

[startup+54.4081 s]
/proc/loadavg: 1.01 1.03 1.00 2/37 19830
/proc/meminfo: memFree=505300/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10680 CPUtime=53.7
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2933 0 0 0 5367 3 0 0 25 0 1 0 4576083 10936320 2461 1283457024 134512640 136285277 4290397584 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2670 2461 234 433 0 2235 0
Current children cumulated CPU time (s) 54.37
Current children cumulated vsize (KiB) 13280

[startup+56.0083 s]
/proc/loadavg: 1.01 1.03 1.00 2/37 19831
/proc/meminfo: memFree=505300/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10680 CPUtime=55.3
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2933 0 0 0 5527 3 0 0 25 0 1 0 4576083 10936320 2461 1283457024 134512640 136285277 4290397584 18446744073709551615 134734338 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2670 2461 234 433 0 2235 0
Current children cumulated CPU time (s) 55.97
Current children cumulated vsize (KiB) 13280

[startup+57.6086 s]
/proc/loadavg: 1.01 1.03 1.00 2/37 19831
/proc/meminfo: memFree=505300/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10680 CPUtime=56.89
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2933 0 0 0 5686 3 0 0 25 0 1 0 4576083 10936320 2461 1283457024 134512640 136285277 4290397584 18446744073709551615 134986656 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2670 2461 234 433 0 2235 0
Current children cumulated CPU time (s) 57.56
Current children cumulated vsize (KiB) 13280

[startup+58.0087 s]
/proc/loadavg: 1.01 1.03 1.00 2/37 19831
/proc/meminfo: memFree=505300/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2600 CPUtime=0.67
/proc/19812/stat : 19812 (aspcud-trendy-1) S 19811 19812 1511 34817 1511 4202496 626 8840 0 0 0 0 63 4 20 0 1 0 4576081 2662400 299 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/19812/statm: 650 299 251 194 0 37 0
[pid=19824] ppid=19812 vsize=10680 CPUtime=57.29
/proc/19824/stat : 19824 (clasp) R 19812 19812 1511 34817 1511 4202496 2933 0 0 0 5726 3 0 0 25 0 1 0 4576083 10936320 2461 1283457024 134512640 136285277 4290397584 18446744073709551615 134966782 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/19824/statm: 2670 2461 234 433 0 2235 0
Current children cumulated CPU time (s) 57.96
Current children cumulated vsize (KiB) 13280

[startup+58.4088 s]
/proc/loadavg: 1.01 1.03 1.00 2/37 19831
/proc/meminfo: memFree=505300/1048576 swapFree=0/0
[pid=19812] ppid=19811 vsize=2700 CPUtime=58.35
/proc/19812/stat : 19812 (aspcud-trendy-1) R 19811 19812 1511 34817 1511 4202496 870 13595 0 0 0 0 5827 8 22 0 1 0 4576081 2764800 325 1283457024 134512640 135304128 4290803264 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/19812/statm: 675 325 256 194 0 62 0
Current children cumulated CPU time (s) 58.35
Current children cumulated vsize (KiB) 2700

Child status: 0
Real time (s): 58.416
CPU time (s): 58.3756
CPU user time (s): 58.2876
CPU system time (s): 0.088005
CPU usage (%): 99.931
Max. virtual memory (cumulated for all children) (KiB): 13280

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 58.2876
system time used= 0.088005
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 16066
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= 539
involuntary context switches= 1205

runsolver used 0 second user time and 0 second system time

The end