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/rand18.cudf.user-upgrades.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/user-upgrades/rand18.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand18.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.21 1.10 1.02 5/35 8841
/proc/meminfo: memFree=495592/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2584 CPUtime=0
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 2126199 2646016 279 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/8839/statm: 646 279 234 194 0 33 0
[pid=8840] ppid=8839 vsize=2584 CPUtime=0
/proc/8840/stat : 8840 (aspcud-trendy-1) S 8839 8839 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 25 0 1 0 2126199 2646016 133 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/8840/statm: 646 133 87 194 0 33 0
[pid=8841] ppid=8840 vsize=2584 CPUtime=0
/proc/8841/stat : 8841 (aspcud-trendy-1) R 8840 8839 1511 34817 1511 4202560 126 0 0 0 0 0 0 0 25 0 1 0 2126199 2646016 150 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/8841/statm: 646 150 104 194 0 33 0
[pid=8842] ppid=8841 vsize=2584 CPUtime=0
/proc/8842/stat : 8842 (aspcud-trendy-1) R 8841 8839 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2126200 2646016 46 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/8842/statm: 646 46 0 194 0 33 0

[startup+0.113933 s]
/proc/loadavg: 1.21 1.10 1.02 5/35 8841
/proc/meminfo: memFree=495592/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=0
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 623 2229 0 0 0 0 0 0 25 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.203958 s]
/proc/loadavg: 1.21 1.10 1.02 5/35 8841
/proc/meminfo: memFree=495592/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=0
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 623 2229 0 0 0 0 0 0 25 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.313996 s]
/proc/loadavg: 1.21 1.10 1.02 5/35 8841
/proc/meminfo: memFree=495592/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=0
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 623 2229 0 0 0 0 0 0 25 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.704127 s]
/proc/loadavg: 1.21 1.10 1.02 5/35 8841
/proc/meminfo: memFree=495592/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=0
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 623 2229 0 0 0 0 0 0 25 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50436 s]
/proc/loadavg: 1.21 1.10 1.02 2/37 8853
/proc/meminfo: memFree=472368/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=0
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 623 2229 0 0 0 0 0 0 25 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
[pid=8851] ppid=8839 vsize=1924 CPUtime=0
/proc/8851/stat : 8851 (clasp) S 8839 8839 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 2126201 1970176 159 1283457024 134512640 136285277 4293931248 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/8851/statm: 481 159 144 433 0 46 0
[pid=8852] ppid=8839 vsize=2584 CPUtime=0
/proc/8852/stat : 8852 (gringo) S 8839 8839 1511 34817 1511 4202496 403 0 0 0 0 0 0 0 25 0 1 0 2126201 2646016 271 1283457024 134512640 136933539 4290653760 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8852/statm: 646 271 242 592 0 51 0
[pid=8853] ppid=8839 vsize=25516 CPUtime=1.49
/proc/8853/stat : 8853 (cudf2lp) R 8839 8839 1511 34817 1511 4202496 7588 0 0 0 147 2 0 0 25 0 1 0 2126201 26128384 5739 1283457024 134512640 135786343 4290031040 18446744073709551615 134796635 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8853/statm: 6379 5739 126 311 0 6066 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 32616

[startup+3.10489 s]
/proc/loadavg: 1.21 1.10 1.02 2/37 8853
/proc/meminfo: memFree=449676/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=2.43
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 624 15597 0 0 0 0 240 3 18 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
[pid=8851] ppid=8839 vsize=15988 CPUtime=0.08
/proc/8851/stat : 8851 (clasp) R 8839 8839 1511 34817 1511 4202496 4296 0 0 0 5 3 0 0 18 0 1 0 2126201 16371712 3642 1283457024 134512640 136285277 4293931248 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8851/statm: 3997 3642 177 433 0 3562 0
[pid=8852] ppid=8839 vsize=25296 CPUtime=0.56
/proc/8852/stat : 8852 (gringo) R 8839 8839 1511 34817 1511 4202496 6643 0 0 0 56 0 0 0 18 0 1 0 2126201 25903104 4964 1283457024 134512640 136933539 4290653760 18446744073709551615 134691753 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8852/statm: 6324 4964 253 592 0 5729 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 43876

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

[startup+3.20493 s]
/proc/loadavg: 1.21 1.10 1.02 2/37 8853
/proc/meminfo: memFree=449676/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=2.43
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 624 15597 0 0 0 0 240 3 18 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
[pid=8851] ppid=8839 vsize=17044 CPUtime=0.1
/proc/8851/stat : 8851 (clasp) R 8839 8839 1511 34817 1511 4202496 4579 0 0 0 7 3 0 0 18 0 1 0 2126201 17453056 3925 1283457024 134512640 136285277 4293931248 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8851/statm: 4261 3925 177 433 0 3826 0
[pid=8852] ppid=8839 vsize=27896 CPUtime=0.64
/proc/8852/stat : 8852 (gringo) R 8839 8839 1511 34817 1511 4202496 7250 0 0 0 64 0 0 0 18 0 1 0 2126201 28565504 5571 1283457024 134512640 136933539 4290653760 18446744073709551615 134726253 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8852/statm: 6974 5571 253 592 0 6379 0
Current children cumulated CPU time (s) 3.17
Current children cumulated vsize (KiB) 47532

[startup+4.00524 s]
/proc/loadavg: 1.21 1.10 1.02 3/36 8853
/proc/meminfo: memFree=454032/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=3.21
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 624 23911 0 0 0 0 314 7 15 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
[pid=8851] ppid=8839 vsize=25632 CPUtime=0.77
/proc/8851/stat : 8851 (clasp) R 8839 8839 1511 34817 1511 4202496 7255 0 0 0 72 5 0 0 18 0 1 0 2126201 26247168 6149 1283457024 134512640 136285277 4293931248 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8851/statm: 6408 6149 234 433 0 5973 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 28224

[startup+4.40536 s]
/proc/loadavg: 1.19 1.10 1.02 2/35 8853
/proc/meminfo: memFree=471160/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=3.21
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 624 23911 0 0 0 0 314 7 15 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
[pid=8851] ppid=8839 vsize=25632 CPUtime=1.17
/proc/8851/stat : 8851 (clasp) R 8839 8839 1511 34817 1511 4202496 7255 0 0 0 112 5 0 0 19 0 1 0 2126201 26247168 6149 1283457024 134512640 136285277 4293931248 18446744073709551615 134931382 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8851/statm: 6408 6149 234 433 0 5973 0
Current children cumulated CPU time (s) 4.38
Current children cumulated vsize (KiB) 28224

[startup+4.80549 s]
/proc/loadavg: 1.19 1.10 1.02 2/35 8853
/proc/meminfo: memFree=471160/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=3.21
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 624 23911 0 0 0 0 314 7 15 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
[pid=8851] ppid=8839 vsize=25632 CPUtime=1.57
/proc/8851/stat : 8851 (clasp) R 8839 8839 1511 34817 1511 4202496 7255 0 0 0 152 5 0 0 19 0 1 0 2126201 26247168 6149 1283457024 134512640 136285277 4293931248 18446744073709551615 134734287 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8851/statm: 6408 6149 234 433 0 5973 0
Current children cumulated CPU time (s) 4.78
Current children cumulated vsize (KiB) 28224

[startup+4.90631 s]
/proc/loadavg: 1.19 1.10 1.02 2/35 8853
/proc/meminfo: memFree=471160/1048576 swapFree=0/0
[pid=8839] ppid=8838 vsize=2592 CPUtime=3.21
/proc/8839/stat : 8839 (aspcud-trendy-1) S 8838 8839 1511 34817 1511 4202496 624 23911 0 0 0 0 314 7 15 0 1 0 2126199 2654208 298 1283457024 134512640 135304128 4294420896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8839/statm: 648 298 251 194 0 35 0
[pid=8851] ppid=8839 vsize=21892 CPUtime=1.67
/proc/8851/stat : 8851 (clasp) R 8839 8839 1511 34817 1511 4202496 7264 0 0 0 161 6 0 0 20 0 1 0 2126201 22417408 4199 1283457024 134512640 136285277 4293931248 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/8851/statm: 5473 4199 242 433 0 5038 0
Current children cumulated CPU time (s) 4.88
Current children cumulated vsize (KiB) 24484

Child status: 0
Real time (s): 4.9294
CPU time (s): 4.91231
CPU user time (s): 4.7523
CPU system time (s): 0.16001
CPU usage (%): 99.6532
Max. virtual memory (cumulated for all children) (KiB): 62784

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

runsolver used 0.012 second user time and 0 second system time

The end