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/rand519.cudf.s-e-l-s-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand519.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand519.cudf.s-e-l-s-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.08 1.13 1.05 5/35 9509
/proc/meminfo: memFree=422188/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2592 CPUtime=0
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 2156967 2654208 280 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/9507/statm: 648 280 234 194 0 35 0
[pid=9508] ppid=9507 vsize=2592 CPUtime=0
/proc/9508/stat : 9508 (aspcud-trendy-1) R 9507 9507 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2156967 2654208 133 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/9508/statm: 648 133 86 194 0 35 0
[pid=9509] ppid=9508 vsize=2592 CPUtime=0
/proc/9509/stat : 9509 (aspcud-trendy-1) R 9508 9507 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2156967 2654208 47 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/9509/statm: 648 47 0 194 0 35 0

[startup+0.145364 s]
/proc/loadavg: 1.08 1.13 1.05 5/35 9509
/proc/meminfo: memFree=422188/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=0.01
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 623 2225 0 0 0 0 0 1 25 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.205373 s]
/proc/loadavg: 1.08 1.13 1.05 5/35 9509
/proc/meminfo: memFree=422188/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=0.01
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 623 2225 0 0 0 0 0 1 25 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.305381 s]
/proc/loadavg: 1.08 1.13 1.05 5/35 9509
/proc/meminfo: memFree=422188/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=0.01
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 623 2225 0 0 0 0 0 1 25 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.705433 s]
/proc/loadavg: 1.08 1.13 1.05 5/35 9509
/proc/meminfo: memFree=422188/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=0.01
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 623 2225 0 0 0 0 0 1 25 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.50552 s]
/proc/loadavg: 1.08 1.13 1.05 2/37 9521
/proc/meminfo: memFree=401320/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=0.01
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 623 2225 0 0 0 0 0 1 25 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=1924 CPUtime=0
/proc/9519/stat : 9519 (clasp) S 9507 9507 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 2156968 1970176 159 1283457024 134512640 136285277 4293560464 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9519/statm: 481 159 144 433 0 46 0
[pid=9520] ppid=9507 vsize=2584 CPUtime=0
/proc/9520/stat : 9520 (gringo) S 9507 9507 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 2156968 2646016 272 1283457024 134512640 136933539 4292515856 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9520/statm: 646 272 242 592 0 51 0
[pid=9521] ppid=9507 vsize=40668 CPUtime=1.5
/proc/9521/stat : 9521 (cudf2lp) R 9507 9507 1511 34817 1511 4202496 11706 0 0 0 140 10 0 0 25 0 1 0 2156968 41644032 8795 1283457024 134512640 135786343 4292769888 18446744073709551615 135208400 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9521/statm: 10167 8795 126 311 0 9854 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 47776

[startup+3.10584 s]
/proc/loadavg: 1.07 1.13 1.05 3/37 9521
/proc/meminfo: memFree=367344/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=0.01
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 623 2225 0 0 0 0 0 1 25 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=17316 CPUtime=0.12
/proc/9519/stat : 9519 (clasp) S 9507 9507 1511 34817 1511 4202496 4796 0 0 0 10 2 0 0 18 0 1 0 2156968 17731584 4005 1283457024 134512640 136285277 4293560464 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9519/statm: 4329 4005 177 433 0 3894 0
[pid=9520] ppid=9507 vsize=22088 CPUtime=0.68
/proc/9520/stat : 9520 (gringo) S 9507 9507 1511 34817 1511 4202496 6890 0 0 0 64 4 0 0 18 0 1 0 2156968 22618112 4617 1283457024 134512640 136933539 4292515856 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9520/statm: 5522 4617 242 592 0 4927 0
[pid=9521] ppid=9507 vsize=17684 CPUtime=2.28
/proc/9521/stat : 9521 (cudf2lp) R 9507 9507 1511 34817 1511 4202496 16202 0 0 0 215 13 0 0 25 0 1 0 2156968 18108416 4243 1283457024 134512640 135786343 4292769888 18446744073709551615 135191523 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9521/statm: 4421 4243 138 311 0 4108 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 59688

[startup+6.30683 s]
/proc/loadavg: 1.07 1.13 1.05 2/35 9521
/proc/meminfo: memFree=367996/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=55472 CPUtime=2.13
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 17025 0 0 0 209 4 0 0 20 0 1 0 2156968 56803328 13624 1283457024 134512640 136285277 4293560464 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 13868 13624 234 433 0 13433 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 58072

[startup+12.7085 s]
/proc/loadavg: 1.06 1.12 1.05 2/35 9521
/proc/meminfo: memFree=368012/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=55472 CPUtime=8.53
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 17037 0 0 0 849 4 0 0 25 0 1 0 2156968 56803328 13636 1283457024 134512640 136285277 4293560464 18446744073709551615 134931346 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 13868 13636 234 433 0 13433 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 58072

[startup+25.5117 s]
/proc/loadavg: 1.05 1.12 1.05 2/35 9521
/proc/meminfo: memFree=340856/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=83856 CPUtime=21.32
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 24125 0 0 0 2126 6 0 0 25 0 1 0 2156968 85868544 20724 1283457024 134512640 136285277 4293560464 18446744073709551615 134623655 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 20964 20724 234 433 0 20529 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 86456

[startup+51.1076 s]
/proc/loadavg: 1.03 1.11 1.05 2/35 9521
/proc/meminfo: memFree=262488/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=165056 CPUtime=46.91
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 44393 0 0 0 4683 8 0 0 25 0 1 0 2156968 169017344 40992 1283457024 134512640 136285277 4293560464 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 41264 40992 234 433 0 40829 0
Current children cumulated CPU time (s) 51.07
Current children cumulated vsize (KiB) 167656

[startup+102.309 s]
/proc/loadavg: 1.01 1.09 1.04 2/35 9521
/proc/meminfo: memFree=192056/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=231920 CPUtime=98.06
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 61090 0 0 0 9787 19 0 0 25 0 1 0 2156968 237486080 57689 1283457024 134512640 136285277 4293560464 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 57980 57689 234 433 0 57545 0
Current children cumulated CPU time (s) 102.22
Current children cumulated vsize (KiB) 234520

[startup+162.305 s]
/proc/loadavg: 1.00 1.07 1.04 2/37 9524
/proc/meminfo: memFree=121724/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=301740 CPUtime=158.02
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 78566 0 0 0 15777 25 0 0 25 0 1 0 2156968 308981760 75165 1283457024 134512640 136285277 4293560464 18446744073709551615 134964956 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 75435 75165 234 433 0 75000 0
Current children cumulated CPU time (s) 162.18
Current children cumulated vsize (KiB) 304340

[startup+222.315 s]
/proc/loadavg: 1.00 1.05 1.03 2/37 9530
/proc/meminfo: memFree=59104/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=364392 CPUtime=218
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 94198 0 0 0 21764 36 0 0 25 0 1 0 2156968 373137408 90797 1283457024 134512640 136285277 4293560464 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 91098 90797 234 433 0 90663 0
Current children cumulated CPU time (s) 222.16
Current children cumulated vsize (KiB) 366992

[startup+282.314 s]
/proc/loadavg: 1.00 1.04 1.03 2/36 9532
/proc/meminfo: memFree=60236/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=362664 CPUtime=277.94
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 94210 0 0 0 27758 36 0 0 25 0 1 0 2156968 371367936 90382 1283457024 134512640 136285277 4293560464 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 90666 90382 234 433 0 90231 0
Current children cumulated CPU time (s) 282.1
Current children cumulated vsize (KiB) 365264



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.308 s]
/proc/loadavg: 1.00 1.04 1.03 2/36 9532
/proc/meminfo: memFree=60236/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=362664 CPUtime=285.91
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 94212 0 0 0 28555 36 0 0 25 0 1 0 2156968 371367936 90384 1283457024 134512640 136285277 4293560464 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 90666 90384 234 433 0 90231 0
Current children cumulated CPU time (s) 290.07
Current children cumulated vsize (KiB) 365264

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+290.308 s]
/proc/loadavg: 1.00 1.04 1.03 2/36 9532
/proc/meminfo: memFree=60236/1048576 swapFree=0/0
[pid=9507] ppid=9506 vsize=2600 CPUtime=4.16
/proc/9507/stat : 9507 (aspcud-trendy-1) S 9506 9507 1511 34817 1511 4202496 624 38019 0 0 0 0 390 26 18 0 1 0 2156967 2662400 299 1283457024 134512640 135304128 4288791616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9507/statm: 650 299 251 194 0 37 0
[pid=9519] ppid=9507 vsize=362664 CPUtime=285.91
/proc/9519/stat : 9519 (clasp) R 9507 9507 1511 34817 1511 4202496 94212 0 0 0 28555 36 0 0 25 0 1 0 2156968 371367936 90384 1283457024 134512640 136285277 4293560464 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9519/statm: 90666 90384 234 433 0 90231 0
Current children cumulated CPU time (s) 290.07
Current children cumulated vsize (KiB) 365264

Child status: 0
Real time (s): 290.354
CPU time (s): 290.134
CPU user time (s): 289.466
CPU system time (s): 0.668041
CPU usage (%): 99.9244
Max. virtual memory (cumulated for all children) (KiB): 366992

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.466
system time used= 0.668041
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 136588
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= 2898
involuntary context switches= 5763

runsolver used 0 second user time and 0 second system time

The end