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/rand152.cudf.user-upgrades.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/user-upgrades/rand152.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand152.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.14 1.06 1.01 5/37 5037
/proc/meminfo: memFree=568144/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2584 CPUtime=0
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 1302513 2646016 279 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/5034/statm: 646 279 234 194 0 33 0
[pid=5035] ppid=5034 vsize=2584 CPUtime=0
/proc/5035/stat : 5035 (aspuncud-trendy) S 5034 5034 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 1302513 2646016 133 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/5035/statm: 646 133 87 194 0 33 0
[pid=5036] ppid=5035 vsize=2584 CPUtime=0
/proc/5036/stat : 5036 (aspuncud-trendy) R 5035 5034 1511 34817 1511 4202560 128 0 0 0 0 0 0 0 25 0 1 0 1302513 2646016 150 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5036/statm: 646 150 104 194 0 33 0
[pid=5037] ppid=5036 vsize=2584 CPUtime=0
/proc/5037/stat : 5037 (aspuncud-trendy) R 5036 5034 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1302513 2646016 46 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5037/statm: 646 46 0 194 0 33 0

[startup+0.182625 s]
/proc/loadavg: 1.14 1.06 1.01 5/37 5037
/proc/meminfo: memFree=568144/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=0.01
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 2232 0 0 0 1 0 0 25 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.206653 s]
/proc/loadavg: 1.14 1.06 1.01 5/37 5037
/proc/meminfo: memFree=568144/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=0.01
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 2232 0 0 0 1 0 0 25 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.306676 s]
/proc/loadavg: 1.14 1.06 1.01 5/37 5037
/proc/meminfo: memFree=568144/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=0.01
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 2232 0 0 0 1 0 0 25 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.706678 s]
/proc/loadavg: 1.14 1.06 1.01 5/37 5037
/proc/meminfo: memFree=568144/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=0.01
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 2232 0 0 0 1 0 0 25 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+1.50669 s]
/proc/loadavg: 1.13 1.06 1.01 1/38 5048
/proc/meminfo: memFree=536064/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=0.01
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 2232 0 0 0 1 0 0 25 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
[pid=5046] ppid=5034 vsize=3444 CPUtime=0
/proc/5046/stat : 5046 (unclasp) S 5034 5034 1511 34817 1511 4202496 406 0 0 0 0 0 0 0 25 0 1 0 1302514 3526656 271 1283457024 134512640 135121179 4290846336 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5046/statm: 861 271 240 149 0 52 0
[pid=5047] ppid=5034 vsize=2692 CPUtime=0
/proc/5047/stat : 5047 (gringo) S 5034 5034 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1302514 2756608 281 1283457024 134512640 137056543 4293199936 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5047/statm: 673 281 252 622 0 48 0
[pid=5048] ppid=5034 vsize=25524 CPUtime=1.29
/proc/5048/stat : 5048 (cudf2lp) R 5034 5034 1511 34817 1511 4202496 7530 0 0 0 126 3 0 0 25 0 1 0 1302514 26136576 5687 1283457024 134512640 135786343 4291524400 18446744073709551615 135199288 0 0 6 0 0 0 0 17 0 0 0 0
/proc/5048/statm: 6381 5687 126 311 0 6068 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 34248

[startup+3.10363 s]
/proc/loadavg: 1.13 1.06 1.01 2/38 5048
/proc/meminfo: memFree=496612/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=2.27
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 15595 0 0 0 1 216 10 18 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
[pid=5046] ppid=5034 vsize=15364 CPUtime=0.06
/proc/5046/stat : 5046 (unclasp) R 5034 5034 1511 34817 1511 4202496 3657 0 0 0 6 0 0 0 18 0 1 0 1302514 15732736 3227 1283457024 134512640 135121179 4290846336 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5046/statm: 3841 3227 277 149 0 3032 0
[pid=5047] ppid=5034 vsize=19320 CPUtime=0.51
/proc/5047/stat : 5047 (gringo) R 5034 5034 1511 34817 1511 4202496 5005 0 0 0 48 3 0 0 18 0 1 0 1302514 19783680 3974 1283457024 134512640 137056543 4293199936 18446744073709551615 134805159 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5047/statm: 4830 3974 268 622 0 4205 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 37272

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

[startup+3.21368 s]
/proc/loadavg: 1.13 1.06 1.01 2/38 5048
/proc/meminfo: memFree=496612/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=2.82
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 20914 0 0 0 1 268 13 17 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
[pid=5046] ppid=5034 vsize=18908 CPUtime=0.14
/proc/5046/stat : 5046 (unclasp) R 5034 5034 1511 34817 1511 4202496 4630 0 0 0 14 0 0 0 18 0 1 0 1302514 19361792 4100 1283457024 134512640 135121179 4290846336 18446744073709551615 134691818 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5046/statm: 4727 4100 296 149 0 3918 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 21496

[startup+4.80413 s]
/proc/loadavg: 1.13 1.06 1.01 2/36 5048
/proc/meminfo: memFree=519336/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=2.82
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 20914 0 0 0 1 268 13 17 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
[pid=5046] ppid=5034 vsize=22480 CPUtime=1.72
/proc/5046/stat : 5046 (unclasp) R 5034 5034 1511 34817 1511 4202496 20334 0 0 0 168 4 0 0 20 0 1 0 1302514 23019520 4840 1283457024 134512640 135121179 4290846336 18446744073709551615 134977944 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5046/statm: 5620 4840 326 149 0 4811 0
Current children cumulated CPU time (s) 4.54
Current children cumulated vsize (KiB) 25068

[startup+5.60434 s]
/proc/loadavg: 1.13 1.06 1.01 2/36 5048
/proc/meminfo: memFree=519212/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=2.82
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 20914 0 0 0 1 268 13 17 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
[pid=5046] ppid=5034 vsize=22668 CPUtime=2.52
/proc/5046/stat : 5046 (unclasp) R 5034 5034 1511 34817 1511 4202496 24024 0 0 0 245 7 0 0 22 0 1 0 1302514 23212032 4908 1283457024 134512640 135121179 4290846336 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5046/statm: 5667 4908 331 149 0 4858 0
Current children cumulated CPU time (s) 5.34
Current children cumulated vsize (KiB) 25256

[startup+6.00445 s]
/proc/loadavg: 1.13 1.06 1.01 2/36 5048
/proc/meminfo: memFree=519212/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=2.82
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 20914 0 0 0 1 268 13 17 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
[pid=5046] ppid=5034 vsize=21764 CPUtime=2.92
/proc/5046/stat : 5046 (unclasp) R 5034 5034 1511 34817 1511 4202496 26672 0 0 0 284 8 0 0 25 0 1 0 1302514 22286336 4716 1283457024 134512640 135121179 4290846336 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5046/statm: 5441 4716 333 149 0 4632 0
Current children cumulated CPU time (s) 5.74
Current children cumulated vsize (KiB) 24352

[startup+6.20449 s]
/proc/loadavg: 1.13 1.06 1.01 2/36 5048
/proc/meminfo: memFree=519212/1048576 swapFree=0/0
[pid=5034] ppid=5033 vsize=2588 CPUtime=2.82
/proc/5034/stat : 5034 (aspuncud-trendy) S 5033 5034 1511 34817 1511 4202496 616 20914 0 0 0 1 268 13 17 0 1 0 1302513 2650112 297 1283457024 134512640 135304128 4292882464 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5034/statm: 647 297 251 194 0 34 0
[pid=5046] ppid=5034 vsize=21764 CPUtime=3.12
/proc/5046/stat : 5046 (unclasp) R 5034 5034 1511 34817 1511 4202496 29024 0 0 0 302 10 0 0 25 0 1 0 1302514 22286336 4716 1283457024 134512640 135121179 4290846336 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5046/statm: 5441 4716 333 149 0 4632 0
Current children cumulated CPU time (s) 5.94
Current children cumulated vsize (KiB) 24352

Child status: 0
Real time (s): 6.26801
CPU time (s): 6.02038
CPU user time (s): 5.74836
CPU system time (s): 0.272017
CPU usage (%): 96.0493
Max. virtual memory (cumulated for all children) (KiB): 64460

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.74836
system time used= 0.272017
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 53473
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= 955
involuntary context switches= 839

runsolver used 0 second user time and 0 second system time

The end