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/201109011757/aspuncud-user-1.0/rand662.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand662.cudf /home/misc2010/tmp/201109011757/aspuncud-user-1.0/rand662.cudf.dudf-random.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-notuptodate,-removed,-changed 

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.00 1.00 6/36 28712
/proc/meminfo: memFree=796392/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2588 CPUtime=0
/proc/28711/stat : 28711 (aspuncud-user-1) R 28710 28711 22717 34817 22717 4202496 367 0 0 0 0 0 0 0 25 0 1 0 72546661 2650112 280 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/28711/statm: 647 280 234 194 0 34 0
[pid=28712] ppid=28711 vsize=2588 CPUtime=0
/proc/28712/stat : 28712 (aspuncud-user-1) R 28711 28711 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72546661 2650112 46 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/28712/statm: 647 46 0 194 0 34 0

[startup+0.140054 s]
/proc/loadavg: 1.00 1.00 1.00 6/36 28712
/proc/meminfo: memFree=796392/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=0
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 577 1519 0 0 0 0 0 0 25 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.210072 s]
/proc/loadavg: 1.00 1.00 1.00 6/36 28712
/proc/meminfo: memFree=796392/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=0
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 577 1519 0 0 0 0 0 0 25 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.310091 s]
/proc/loadavg: 1.00 1.00 1.00 6/36 28712
/proc/meminfo: memFree=796392/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=0
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 577 1519 0 0 0 0 0 0 25 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.710172 s]
/proc/loadavg: 1.00 1.00 1.00 6/36 28712
/proc/meminfo: memFree=796392/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=0
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 577 1519 0 0 0 0 0 0 25 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.51032 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 28722
/proc/meminfo: memFree=767864/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=0
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 577 1519 0 0 0 0 0 0 25 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=3444 CPUtime=0
/proc/28720/stat : 28720 (unclasp) S 28711 28711 22717 34817 22717 4202496 407 0 0 0 0 0 0 0 25 0 1 0 72546663 3526656 271 1283457024 134512640 135121179 4290928272 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/28720/statm: 861 271 240 149 0 52 0
[pid=28721] ppid=28711 vsize=2692 CPUtime=0
/proc/28721/stat : 28721 (gringo) S 28711 28711 22717 34817 22717 4202496 409 0 0 0 0 0 0 0 25 0 1 0 72546663 2756608 281 1283457024 134512640 137056543 4290432432 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/28721/statm: 673 281 252 622 0 48 0
[pid=28722] ppid=28711 vsize=29448 CPUtime=1.48
/proc/28722/stat : 28722 (cudf2lp) R 28711 28711 22717 34817 22717 4202496 8198 0 0 0 145 3 0 0 25 0 1 0 72546663 30154752 6701 1283457024 134512640 135786343 4286990976 18446744073709551615 134566250 0 0 6 0 0 0 0 17 0 0 0 0
/proc/28722/statm: 7362 6701 128 311 0 7049 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 38176

[startup+3.11057 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 28723
/proc/meminfo: memFree=747032/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=0
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 577 1519 0 0 0 0 0 0 25 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=13136 CPUtime=0.03
/proc/28720/stat : 28720 (unclasp) S 28711 28711 22717 34817 22717 4202496 3190 0 0 0 3 0 0 0 18 0 1 0 72546663 13451264 2668 1283457024 134512640 135121179 4290928272 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/28720/statm: 3284 2668 275 149 0 2475 0
[pid=28721] ppid=28711 vsize=16316 CPUtime=0.53
/proc/28721/stat : 28721 (gringo) S 28711 28711 22717 34817 22717 4202496 4650 0 0 0 53 0 0 0 18 0 1 0 72546663 16707584 3089 1283457024 134512640 137056543 4290432432 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/28721/statm: 4079 3089 253 622 0 3454 0
[pid=28722] ppid=28711 vsize=25480 CPUtime=2.51
/proc/28722/stat : 28722 (cudf2lp) R 28711 28711 22717 34817 22717 4202496 14079 0 0 0 239 12 0 0 25 0 1 0 72546663 26091520 6194 1283457024 134512640 135786343 4286990976 18446744073709551615 134922544 0 0 6 0 0 0 0 17 0 0 0 0
/proc/28722/statm: 6370 6194 139 311 0 6057 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 57524

[startup+6.31332 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28723
/proc/meminfo: memFree=767960/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=31892 CPUtime=2.78
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 26462 0 1 0 270 8 0 0 22 0 1 0 72546663 32657408 7165 1283457024 134512640 135121179 4290928272 18446744073709551615 134734256 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 7973 7165 328 149 0 7164 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 34484

[startup+12.7059 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28724
/proc/meminfo: memFree=767720/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32672 CPUtime=9.18
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59352 0 1 0 891 27 0 0 25 0 1 0 72546663 33456128 7323 1283457024 134512640 135121179 4290928272 18446744073709551615 134713300 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8168 7323 328 149 0 7359 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 35264

[startup+25.5109 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28725
/proc/meminfo: memFree=767472/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32928 CPUtime=21.98
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59421 0 1 0 2170 28 0 0 25 0 1 0 72546663 33718272 7392 1283457024 134512640 135121179 4290928272 18446744073709551615 134734462 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8232 7392 328 149 0 7423 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 35520

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

[startup+25.611 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28725
/proc/meminfo: memFree=767472/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32928 CPUtime=22.08
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59421 0 1 0 2180 28 0 0 25 0 1 0 72546663 33718272 7392 1283457024 134512640 135121179 4290928272 18446744073709551615 134990522 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8232 7392 328 149 0 7423 0
Current children cumulated CPU time (s) 25.56
Current children cumulated vsize (KiB) 35520

[startup+38.4051 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28726
/proc/meminfo: memFree=767596/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=33000 CPUtime=34.86
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59629 0 1 0 3458 28 0 0 25 0 1 0 72546663 33792000 7405 1283457024 134512640 135121179 4290928272 18446744073709551615 134979236 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8250 7405 328 149 0 7441 0
Current children cumulated CPU time (s) 38.34
Current children cumulated vsize (KiB) 35592

[startup+41.6061 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28726
/proc/meminfo: memFree=767348/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32360 CPUtime=38.06
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59629 0 1 0 3778 28 0 0 25 0 1 0 72546663 33136640 7277 1283457024 134512640 135121179 4290928272 18446744073709551615 134990484 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8090 7277 328 149 0 7281 0
Current children cumulated CPU time (s) 41.54
Current children cumulated vsize (KiB) 34952

[startup+44.8072 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28727
/proc/meminfo: memFree=767348/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32360 CPUtime=41.26
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59629 0 1 0 4098 28 0 0 25 0 1 0 72546663 33136640 7277 1283457024 134512640 135121179 4290928272 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8090 7277 328 149 0 7281 0
Current children cumulated CPU time (s) 44.74
Current children cumulated vsize (KiB) 34952

[startup+46.4076 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28727
/proc/meminfo: memFree=767224/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32812 CPUtime=42.87
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59877 0 1 0 4257 30 0 0 25 0 1 0 72546663 33599488 7358 1283457024 134512640 135121179 4290928272 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8203 7358 328 149 0 7394 0
Current children cumulated CPU time (s) 46.35
Current children cumulated vsize (KiB) 35404

[startup+47.2078 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28727
/proc/meminfo: memFree=767224/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32812 CPUtime=43.67
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59877 0 1 0 4337 30 0 0 25 0 1 0 72546663 33599488 7358 1283457024 134512640 135121179 4290928272 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8203 7358 328 149 0 7394 0
Current children cumulated CPU time (s) 47.15
Current children cumulated vsize (KiB) 35404

[startup+47.408 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 28727
/proc/meminfo: memFree=767224/1048576 swapFree=0/0
[pid=28711] ppid=28710 vsize=2592 CPUtime=3.48
/proc/28711/stat : 28711 (aspuncud-user-1) S 28710 28711 22717 34817 22717 4202496 578 24704 0 0 0 0 331 17 15 0 1 0 72546661 2654208 298 1283457024 134512640 135304128 4290192672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/28711/statm: 648 298 251 194 0 35 0
[pid=28720] ppid=28711 vsize=32812 CPUtime=43.87
/proc/28720/stat : 28720 (unclasp) R 28711 28711 22717 34817 22717 4202496 59877 0 1 0 4357 30 0 0 25 0 1 0 72546663 33599488 7358 1283457024 134512640 135121179 4290928272 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/28720/statm: 8203 7358 328 149 0 7394 0
Current children cumulated CPU time (s) 47.35
Current children cumulated vsize (KiB) 35404

Child status: 0
Real time (s): 47.4607
CPU time (s): 47.411
CPU user time (s): 46.9189
CPU system time (s): 0.49203
CPU usage (%): 99.8952
Max. virtual memory (cumulated for all children) (KiB): 77856

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 46.9189
system time used= 0.49203
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 87683
page faults= 1
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1481
involuntary context switches= 1660

runsolver used 0 second user time and 0.008 second system time

The end