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/aspuncud-trendy-1.3/rand598.cudf.s-e-l.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l/rand598.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand598.cudf.s-e-l.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.00 1.02 1.00 5/37 17413
/proc/meminfo: memFree=697604/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2588 CPUtime=0
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 4029719 2650112 279 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/17410/statm: 647 279 234 194 0 34 0
[pid=17411] ppid=17410 vsize=2588 CPUtime=0
/proc/17411/stat : 17411 (aspuncud-trendy) S 17410 17410 1511 34817 1511 4202560 119 0 0 0 0 0 0 0 18 0 1 0 4029719 2650112 133 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/17411/statm: 647 133 87 194 0 34 0
[pid=17412] ppid=17411 vsize=2588 CPUtime=0
/proc/17412/stat : 17412 (aspuncud-trendy) R 17411 17410 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 4029719 2650112 150 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/17412/statm: 647 150 104 194 0 34 0
[pid=17413] ppid=17412 vsize=2588 CPUtime=0
/proc/17413/stat : 17413 (aspuncud-trendy) R 17412 17410 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4029719 2650112 46 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/17413/statm: 647 46 0 194 0 34 0

[startup+0.150547 s]
/proc/loadavg: 1.00 1.02 1.00 5/37 17413
/proc/meminfo: memFree=697604/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=0
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 2232 0 0 0 0 0 0 25 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.206529 s]
/proc/loadavg: 1.00 1.02 1.00 5/37 17413
/proc/meminfo: memFree=697604/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=0
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 2232 0 0 0 0 0 0 25 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.306535 s]
/proc/loadavg: 1.00 1.02 1.00 5/37 17413
/proc/meminfo: memFree=697604/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=0
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 2232 0 0 0 0 0 0 25 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.715582 s]
/proc/loadavg: 1.00 1.02 1.00 5/37 17413
/proc/meminfo: memFree=697604/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=0
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 2232 0 0 0 0 0 0 25 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.51597 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 17424
/proc/meminfo: memFree=654464/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=0
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 2232 0 0 0 0 0 0 25 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=7748 CPUtime=0
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 1581 0 0 0 0 0 0 0 18 0 1 0 4029720 7933952 1364 1283457024 134512640 135121179 4294584848 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 1937 1364 275 149 0 1128 0
[pid=17423] ppid=17410 vsize=9144 CPUtime=0.2
/proc/17423/stat : 17423 (gringo) R 17410 17410 1511 34817 1511 4202496 2390 0 0 0 18 2 0 0 18 0 1 0 4029721 9363456 1585 1283457024 134512640 137056543 4288500688 18446744073709551615 134727747 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17423/statm: 2286 1585 253 622 0 1661 0
[pid=17424] ppid=17410 vsize=30576 CPUtime=1.18
/proc/17424/stat : 17424 (cudf2lp) R 17410 17410 1511 34817 1511 4202496 10049 0 0 0 116 2 0 0 25 0 1 0 4029721 31309824 7426 1283457024 134512640 135786343 4289697136 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/17424/statm: 7644 7426 137 311 0 7331 0
Current children cumulated CPU time (s) 1.38
Current children cumulated vsize (KiB) 50060

[startup+3.10631 s]
/proc/loadavg: 1.00 1.02 1.00 3/37 17424
/proc/meminfo: memFree=649892/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=30996 CPUtime=0.92
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 12389 0 0 0 84 8 0 0 19 0 1 0 4029720 31739904 6804 1283457024 134512640 135121179 4294584848 18446744073709551615 134734434 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7749 6804 328 149 0 6940 0
Current children cumulated CPU time (s) 2.97
Current children cumulated vsize (KiB) 33588

[startup+6.30749 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=658100/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=31612 CPUtime=4.12
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 40322 0 0 0 389 23 0 0 25 0 1 0 4029720 32370688 6940 1283457024 134512640 135121179 4294584848 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7903 6940 328 149 0 7094 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 34204

[startup+12.7101 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=657480/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=30996 CPUtime=10.52
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 93136 0 0 0 1007 45 0 0 25 0 1 0 4029720 31739904 6805 1283457024 134512640 135121179 4294584848 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7749 6805 328 149 0 6940 0
Current children cumulated CPU time (s) 12.57
Current children cumulated vsize (KiB) 33588

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

[startup+12.8101 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=657480/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=30996 CPUtime=10.62
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 94006 0 0 0 1017 45 0 0 25 0 1 0 4029720 31739904 6805 1283457024 134512640 135121179 4294584848 18446744073709551615 134891399 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7749 6805 328 149 0 6940 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 33588

[startup+14.4108 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=657852/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=30792 CPUtime=12.22
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 107310 0 0 0 1174 48 0 0 25 0 1 0 4029720 31531008 6735 1283457024 134512640 135121179 4294584848 18446744073709551615 134734307 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7698 6735 328 149 0 6889 0
Current children cumulated CPU time (s) 14.27
Current children cumulated vsize (KiB) 33384

[startup+16.0116 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=657852/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=30512 CPUtime=13.82
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 120278 0 0 0 1326 56 0 0 25 0 1 0 4029720 31244288 6666 1283457024 134512640 135121179 4294584848 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7628 6666 328 149 0 6819 0
Current children cumulated CPU time (s) 15.87
Current children cumulated vsize (KiB) 33104

[startup+16.8119 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=657728/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=30996 CPUtime=14.62
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 126367 0 0 0 1403 59 0 0 25 0 1 0 4029720 31739904 6810 1283457024 134512640 135121179 4294584848 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7749 6810 328 149 0 6940 0
Current children cumulated CPU time (s) 16.67
Current children cumulated vsize (KiB) 33588

[startup+17.2121 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=657728/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=31576 CPUtime=15.02
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 126508 0 0 0 1443 59 0 0 25 0 1 0 4029720 32333824 6951 1283457024 134512640 135121179 4294584848 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7894 6951 328 149 0 7085 0
Current children cumulated CPU time (s) 17.07
Current children cumulated vsize (KiB) 34168

[startup+17.3122 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 17424
/proc/meminfo: memFree=657728/1048576 swapFree=0/0
[pid=17410] ppid=17409 vsize=2592 CPUtime=2.05
/proc/17410/stat : 17410 (aspuncud-trendy) S 17409 17410 1511 34817 1511 4202496 617 20351 0 0 0 0 195 10 16 0 1 0 4029719 2654208 297 1283457024 134512640 135304128 4290235808 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17410/statm: 648 297 251 194 0 35 0
[pid=17422] ppid=17410 vsize=31372 CPUtime=15.12
/proc/17422/stat : 17422 (unclasp) R 17410 17410 1511 34817 1511 4202496 126841 0 0 0 1452 60 0 0 25 0 1 0 4029720 32124928 6882 1283457024 134512640 135121179 4294584848 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/17422/statm: 7843 6882 328 149 0 7034 0
Current children cumulated CPU time (s) 17.17
Current children cumulated vsize (KiB) 33964

Child status: 0
Real time (s): 17.3617
CPU time (s): 17.2291
CPU user time (s): 16.509
CPU system time (s): 0.720045
CPU usage (%): 99.2361
Max. virtual memory (cumulated for all children) (KiB): 60912

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 16.509
system time used= 0.720045
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 150285
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= 1228
involuntary context switches= 1106

runsolver used 0 second user time and 0.012 second system time

The end