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/rand105.cudf.user-upgrades.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/user-upgrades/rand105.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand105.cudf.user-upgrades.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.01 0.96 5/35 3271
/proc/meminfo: memFree=685180/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2584 CPUtime=0
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 954235 2646016 279 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/3269/statm: 646 279 234 194 0 33 0
[pid=3270] ppid=3269 vsize=2584 CPUtime=0
/proc/3270/stat : 3270 (aspcud-trendy-1) S 3269 3269 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 25 0 1 0 954235 2646016 133 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/3270/statm: 646 133 87 194 0 33 0
[pid=3271] ppid=3270 vsize=2584 CPUtime=0
/proc/3271/stat : 3271 (aspcud-trendy-1) R 3270 3269 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 954235 2646016 150 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3271/statm: 646 150 104 194 0 33 0
[pid=3272] ppid=3271 vsize=2584 CPUtime=0
/proc/3272/stat : 3272 (aspcud-trendy-1) R 3271 3269 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 954235 2646016 46 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3272/statm: 646 46 0 194 0 33 0

[startup+0.11396 s]
/proc/loadavg: 1.00 1.01 0.96 5/35 3271
/proc/meminfo: memFree=685180/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=0
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 625 2233 0 0 0 0 0 0 25 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.203972 s]
/proc/loadavg: 1.00 1.01 0.96 5/35 3271
/proc/meminfo: memFree=685180/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=0
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 625 2233 0 0 0 0 0 0 25 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.313985 s]
/proc/loadavg: 1.00 1.01 0.96 5/35 3271
/proc/meminfo: memFree=685180/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=0
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 625 2233 0 0 0 0 0 0 25 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.704027 s]
/proc/loadavg: 1.00 1.01 0.96 5/35 3271
/proc/meminfo: memFree=685180/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=0
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 625 2233 0 0 0 0 0 0 25 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50423 s]
/proc/loadavg: 1.00 1.01 0.96 2/37 3283
/proc/meminfo: memFree=661088/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=0
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 625 2233 0 0 0 0 0 0 25 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
[pid=3281] ppid=3269 vsize=1928 CPUtime=0
/proc/3281/stat : 3281 (clasp) S 3269 3269 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 954236 1974272 159 1283457024 134512640 136285277 4291137088 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/3281/statm: 482 159 144 433 0 47 0
[pid=3282] ppid=3269 vsize=2584 CPUtime=0
/proc/3282/stat : 3282 (gringo) S 3269 3269 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 954236 2646016 272 1283457024 134512640 136933539 4292837472 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3282/statm: 646 272 242 592 0 51 0
[pid=3283] ppid=3269 vsize=25516 CPUtime=1.48
/proc/3283/stat : 3283 (cudf2lp) R 3269 3269 1511 34817 1511 4202496 7586 0 0 0 143 5 0 0 25 0 1 0 954236 26128384 5737 1283457024 134512640 135786343 4290592336 18446744073709551615 135199268 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3283/statm: 6379 5737 126 311 0 6066 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 32620

[startup+3.10472 s]
/proc/loadavg: 1.00 1.01 0.96 2/37 3283
/proc/meminfo: memFree=639264/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=2.43
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 626 15601 0 0 0 0 233 10 18 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
[pid=3281] ppid=3269 vsize=15860 CPUtime=0.09
/proc/3281/stat : 3281 (clasp) R 3269 3269 1511 34817 1511 4202496 4263 0 0 0 6 3 0 0 18 0 1 0 954236 16240640 3609 1283457024 134512640 136285277 4291137088 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3281/statm: 3965 3609 177 433 0 3530 0
[pid=3282] ppid=3269 vsize=25296 CPUtime=0.55
/proc/3282/stat : 3282 (gringo) R 3269 3269 1511 34817 1511 4202496 6631 0 0 0 53 2 0 0 18 0 1 0 954236 25903104 4952 1283457024 134512640 136933539 4292837472 18446744073709551615 134688168 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3282/statm: 6324 4952 253 592 0 5729 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 43748

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

[startup+3.20475 s]
/proc/loadavg: 1.00 1.01 0.96 2/37 3283
/proc/meminfo: memFree=639264/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=2.43
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 626 15601 0 0 0 0 233 10 18 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
[pid=3281] ppid=3269 vsize=16784 CPUtime=0.14
/proc/3281/stat : 3281 (clasp) R 3269 3269 1511 34817 1511 4202496 4520 0 0 0 10 4 0 0 18 0 1 0 954236 17186816 3866 1283457024 134512640 136285277 4291137088 18446744073709551615 134782651 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3281/statm: 4196 3866 177 433 0 3761 0
[pid=3282] ppid=3269 vsize=27404 CPUtime=0.61
/proc/3282/stat : 3282 (gringo) R 3269 3269 1511 34817 1511 4202496 7150 0 0 0 59 2 0 0 18 0 1 0 954236 28061696 5471 1283457024 134512640 136933539 4292837472 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3282/statm: 6851 5471 253 592 0 6256 0
Current children cumulated CPU time (s) 3.18
Current children cumulated vsize (KiB) 46780

[startup+4.00497 s]
/proc/loadavg: 1.08 1.02 0.96 3/36 3283
/proc/meminfo: memFree=642504/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=3.17
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 626 23913 0 0 0 0 303 14 15 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
[pid=3281] ppid=3269 vsize=25704 CPUtime=0.82
/proc/3281/stat : 3281 (clasp) R 3269 3269 1511 34817 1511 4202496 7272 0 0 0 78 4 0 0 18 0 1 0 954236 26320896 6166 1283457024 134512640 136285277 4291137088 18446744073709551615 134931009 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3281/statm: 6426 6166 234 433 0 5991 0
Current children cumulated CPU time (s) 3.99
Current children cumulated vsize (KiB) 28296

[startup+4.40507 s]
/proc/loadavg: 1.08 1.02 0.96 2/35 3283
/proc/meminfo: memFree=660748/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=3.17
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 626 23913 0 0 0 0 303 14 15 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
[pid=3281] ppid=3269 vsize=25704 CPUtime=1.22
/proc/3281/stat : 3281 (clasp) R 3269 3269 1511 34817 1511 4202496 7272 0 0 0 118 4 0 0 19 0 1 0 954236 26320896 6166 1283457024 134512640 136285277 4291137088 18446744073709551615 134669462 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3281/statm: 6426 6166 234 433 0 5991 0
Current children cumulated CPU time (s) 4.39
Current children cumulated vsize (KiB) 28296

[startup+4.60512 s]
/proc/loadavg: 1.08 1.02 0.96 2/35 3283
/proc/meminfo: memFree=660748/1048576 swapFree=0/0
[pid=3269] ppid=3268 vsize=2592 CPUtime=3.17
/proc/3269/stat : 3269 (aspcud-trendy-1) S 3268 3269 1511 34817 1511 4202496 626 23913 0 0 0 0 303 14 15 0 1 0 954235 2654208 298 1283457024 134512640 135304128 4293935408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3269/statm: 648 298 251 194 0 35 0
[pid=3281] ppid=3269 vsize=25704 CPUtime=1.42
/proc/3281/stat : 3281 (clasp) R 3269 3269 1511 34817 1511 4202496 7272 0 0 0 138 4 0 0 19 0 1 0 954236 26320896 6166 1283457024 134512640 136285277 4291137088 18446744073709551615 134959967 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3281/statm: 6426 6166 234 433 0 5991 0
Current children cumulated CPU time (s) 4.59
Current children cumulated vsize (KiB) 28296

Child status: 0
Real time (s): 4.6485
CPU time (s): 4.63629
CPU user time (s): 4.42428
CPU system time (s): 0.212013
CPU usage (%): 99.7373
Max. virtual memory (cumulated for all children) (KiB): 62656

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.42428
system time used= 0.212013
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 35440
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= 917
involuntary context switches= 685

runsolver used 0 second user time and 0.012 second system time

The end