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/rand994.cudf.user-upgrades.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/user-upgrades/rand994.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand994.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.25 1.15 1.10 5/35 27116
/proc/meminfo: memFree=284152/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2588 CPUtime=0
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 4846615 2650112 279 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/27114/statm: 647 279 234 194 0 34 0
[pid=27115] ppid=27114 vsize=2588 CPUtime=0
/proc/27115/stat : 27115 (aspcud-trendy-1) R 27114 27114 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4846616 2650112 132 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/27115/statm: 647 132 86 194 0 34 0
[pid=27116] ppid=27115 vsize=2588 CPUtime=0
/proc/27116/stat : 27116 (aspcud-trendy-1) R 27115 27114 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4846616 2650112 46 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/27116/statm: 647 46 0 194 0 34 0

[startup+0.175228 s]
/proc/loadavg: 1.25 1.15 1.10 5/35 27116
/proc/meminfo: memFree=284152/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=0.01
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 623 2231 0 0 0 0 0 1 25 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.20523 s]
/proc/loadavg: 1.25 1.15 1.10 5/35 27116
/proc/meminfo: memFree=284152/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=0.01
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 623 2231 0 0 0 0 0 1 25 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.305253 s]
/proc/loadavg: 1.25 1.15 1.10 5/35 27116
/proc/meminfo: memFree=284152/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=0.01
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 623 2231 0 0 0 0 0 1 25 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.705326 s]
/proc/loadavg: 1.25 1.15 1.10 5/35 27116
/proc/meminfo: memFree=284152/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=0.01
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 623 2231 0 0 0 0 0 1 25 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50549 s]
/proc/loadavg: 1.25 1.15 1.10 2/37 27128
/proc/meminfo: memFree=259564/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=0.01
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 623 2231 0 0 0 0 0 1 25 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
[pid=27126] ppid=27114 vsize=1932 CPUtime=0
/proc/27126/stat : 27126 (clasp) S 27114 27114 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 4846617 1978368 160 1283457024 134512640 136285277 4289061952 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/27126/statm: 483 160 144 433 0 48 0
[pid=27127] ppid=27114 vsize=2584 CPUtime=0
/proc/27127/stat : 27127 (gringo) S 27114 27114 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 4846617 2646016 272 1283457024 134512640 136933539 4293288128 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/27127/statm: 646 272 242 592 0 51 0
[pid=27128] ppid=27114 vsize=25520 CPUtime=1.49
/proc/27128/stat : 27128 (cudf2lp) R 27114 27114 1511 34817 1511 4202496 7590 0 0 0 145 4 0 0 25 0 1 0 4846617 26132480 5741 1283457024 134512640 135786343 4291989408 18446744073709551615 134796970 0 0 6 0 0 0 0 17 0 0 0 0
/proc/27128/statm: 6380 5741 126 311 0 6067 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 32632

[startup+3.10582 s]
/proc/loadavg: 1.23 1.15 1.10 2/37 27128
/proc/meminfo: memFree=238236/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=2.42
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 624 15600 0 0 0 0 234 8 18 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
[pid=27126] ppid=27114 vsize=15864 CPUtime=0.06
/proc/27126/stat : 27126 (clasp) R 27114 27114 1511 34817 1511 4202496 4280 0 0 0 4 2 0 0 18 0 1 0 4846617 16244736 3626 1283457024 134512640 136285277 4289061952 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/27126/statm: 3966 3626 177 433 0 3531 0
[pid=27127] ppid=27114 vsize=25300 CPUtime=0.61
/proc/27127/stat : 27127 (gringo) R 27114 27114 1511 34817 1511 4202496 6631 0 0 0 60 1 0 0 18 0 1 0 4846617 25907200 4952 1283457024 134512640 136933539 4293288128 18446744073709551615 135748049 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27127/statm: 6325 4952 253 592 0 5730 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 43760

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

[startup+3.20584 s]
/proc/loadavg: 1.23 1.15 1.10 2/37 27128
/proc/meminfo: memFree=238236/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=2.42
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 624 15600 0 0 0 0 234 8 18 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
[pid=27126] ppid=27114 vsize=17052 CPUtime=0.09
/proc/27126/stat : 27126 (clasp) R 27114 27114 1511 34817 1511 4202496 4573 0 0 0 7 2 0 0 18 0 1 0 4846617 17461248 3919 1283457024 134512640 136285277 4289061952 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/27126/statm: 4263 3919 177 433 0 3828 0
[pid=27127] ppid=27114 vsize=27896 CPUtime=0.67
/proc/27127/stat : 27127 (gringo) R 27114 27114 1511 34817 1511 4202496 7250 0 0 0 66 1 0 0 18 0 1 0 4846617 28565504 5571 1283457024 134512640 136933539 4293288128 18446744073709551615 136204818 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27127/statm: 6974 5571 253 592 0 6379 0
Current children cumulated CPU time (s) 3.18
Current children cumulated vsize (KiB) 47544

[startup+4.00606 s]
/proc/loadavg: 1.23 1.15 1.10 3/36 27128
/proc/meminfo: memFree=240484/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=3.23
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 624 23912 0 0 0 0 310 13 15 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
[pid=27126] ppid=27114 vsize=25700 CPUtime=0.76
/proc/27126/stat : 27126 (clasp) R 27114 27114 1511 34817 1511 4202496 7272 0 0 0 73 3 0 0 18 0 1 0 4846617 26316800 6166 1283457024 134512640 136285277 4289061952 18446744073709551615 134669442 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/27126/statm: 6425 6166 234 433 0 5990 0
Current children cumulated CPU time (s) 3.99
Current children cumulated vsize (KiB) 28296

[startup+4.80626 s]
/proc/loadavg: 1.23 1.15 1.10 2/35 27128
/proc/meminfo: memFree=259720/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=3.23
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 624 23912 0 0 0 0 310 13 15 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
[pid=27126] ppid=27114 vsize=25700 CPUtime=1.56
/proc/27126/stat : 27126 (clasp) R 27114 27114 1511 34817 1511 4202496 7272 0 0 0 153 3 0 0 19 0 1 0 4846617 26316800 6166 1283457024 134512640 136285277 4289061952 18446744073709551615 134629375 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/27126/statm: 6425 6166 234 433 0 5990 0
Current children cumulated CPU time (s) 4.79
Current children cumulated vsize (KiB) 28296

[startup+5.00629 s]
/proc/loadavg: 1.23 1.15 1.10 2/35 27128
/proc/meminfo: memFree=259720/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=3.23
/proc/27114/stat : 27114 (aspcud-trendy-1) S 27113 27114 1511 34817 1511 4202496 624 23912 0 0 0 0 310 13 15 0 1 0 4846615 2658304 298 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27114/statm: 649 298 251 194 0 36 0
[pid=27126] ppid=27114 vsize=25700 CPUtime=1.76
/proc/27126/stat : 27126 (clasp) R 27114 27114 1511 34817 1511 4202496 7272 0 0 0 173 3 0 0 20 0 1 0 4846617 26316800 6166 1283457024 134512640 136285277 4289061952 18446744073709551615 134960178 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/27126/statm: 6425 6166 234 433 0 5990 0
Current children cumulated CPU time (s) 4.99
Current children cumulated vsize (KiB) 28296

[startup+5.10636 s]
/proc/loadavg: 1.23 1.15 1.10 2/35 27128
/proc/meminfo: memFree=259720/1048576 swapFree=0/0
[pid=27114] ppid=27113 vsize=2596 CPUtime=5.09
/proc/27114/stat : 27114 (aspcud-trendy-1) R 27113 27114 1511 34817 1511 4202496 806 32609 0 0 0 0 491 18 19 0 1 0 4846615 2658304 303 1283457024 134512640 135304128 4287105696 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/27114/statm: 649 303 256 194 0 36 0
Current children cumulated CPU time (s) 5.09
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 5.11758
CPU time (s): 5.12032
CPU user time (s): 4.91231
CPU system time (s): 0.208013
CPU usage (%): 100.054
Max. virtual memory (cumulated for all children) (KiB): 62800

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.91231
system time used= 0.208013
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 35449
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= 919
involuntary context switches= 694

runsolver used 0 second user time and 0 second system time

The end