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/packup2mp4tr-0.6/rand105.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand105.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/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.14 1.04 0.97 4/34 3354
/proc/meminfo: memFree=685012/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=3560 CPUtime=0.01
/proc/3354/stat : 3354 (packup) R 3353 3353 1511 34817 1511 4202496 370 0 0 0 0 1 0 0 25 0 1 0 955879 3645440 299 1283457024 134512640 134752139 4287517408 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3354/statm: 890 299 262 59 0 54 0

[startup+0.203459 s]
/proc/loadavg: 1.14 1.04 0.97 4/34 3354
/proc/meminfo: memFree=685012/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=9936 CPUtime=0.21
/proc/3354/stat : 3354 (packup) R 3353 3353 1511 34817 1511 4202496 1962 0 0 0 20 1 0 0 25 0 1 0 955879 10174464 1891 1283457024 134512640 134752139 4287517408 18446744073709551615 4157443646 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3354/statm: 2484 1891 286 59 0 1648 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12508

[startup+0.313471 s]
/proc/loadavg: 1.14 1.04 0.97 4/34 3354
/proc/meminfo: memFree=685012/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=12732 CPUtime=0.31
/proc/3354/stat : 3354 (packup) R 3353 3353 1511 34817 1511 4202496 2672 0 0 0 30 1 0 0 25 0 1 0 955879 13037568 2601 1283457024 134512640 134752139 4287517408 18446744073709551615 134681623 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3354/statm: 3183 2601 286 59 0 2347 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15304

[startup+0.40349 s]
/proc/loadavg: 1.14 1.04 0.97 4/34 3354
/proc/meminfo: memFree=685012/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=14976 CPUtime=0.41
/proc/3354/stat : 3354 (packup) R 3353 3353 1511 34817 1511 4202496 3246 0 0 0 39 2 0 0 25 0 1 0 955879 15335424 3175 1283457024 134512640 134752139 4287517408 18446744073709551615 134639811 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3354/statm: 3744 3175 286 59 0 2908 0
Current children cumulated CPU time (s) 0.41
Current children cumulated vsize (KiB) 17548

[startup+0.71353 s]
/proc/loadavg: 1.14 1.04 0.97 4/34 3354
/proc/meminfo: memFree=685012/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=21920 CPUtime=0.72
/proc/3354/stat : 3354 (packup) R 3353 3353 1511 34817 1511 4202496 4976 0 0 0 68 4 0 0 25 0 1 0 955879 22446080 4905 1283457024 134512640 134752139 4287517408 18446744073709551615 4157430614 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3354/statm: 5480 4905 286 59 0 4644 0
Current children cumulated CPU time (s) 0.72
Current children cumulated vsize (KiB) 24492

[startup+1.51366 s]
/proc/loadavg: 1.14 1.04 0.97 2/35 3355
/proc/meminfo: memFree=656604/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=46084 CPUtime=1.52
/proc/3354/stat : 3354 (packup) R 3353 3353 1511 34817 1511 4202496 11088 0 0 0 144 8 0 0 25 0 1 0 955879 47190016 10825 1283457024 134512640 134752139 4287517408 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3354/statm: 11521 10825 322 59 0 10685 0
Current children cumulated CPU time (s) 1.52
Current children cumulated vsize (KiB) 48656

[startup+3.11399 s]
/proc/loadavg: 1.13 1.04 0.97 2/37 3357
/proc/meminfo: memFree=628672/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=46088 CPUtime=3
/proc/3354/stat : 3354 (packup) S 3353 3353 1511 34817 1511 4202496 11176 8018 0 0 166 26 94 14 18 0 1 0 955879 47194112 10843 1283457024 134512640 134752139 4287517408 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3354/statm: 11522 10843 333 59 0 10686 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 48660

[startup+6.30472 s]
/proc/loadavg: 1.13 1.04 0.97 2/37 3361
/proc/meminfo: memFree=628432/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=46092 CPUtime=5.02
/proc/3354/stat : 3354 (packup) S 3353 3353 1511 34817 1511 4202496 11258 23320 0 0 176 38 260 28 18 0 1 0 955879 47198208 10863 1283457024 134512640 134752139 4287517408 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3354/statm: 11523 10863 333 59 0 10687 0
[pid=3360] ppid=3354 vsize=1672 CPUtime=0
/proc/3360/stat : 3360 (sh) S 3354 3353 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 956383 1712128 123 1283457024 134512640 134593992 4287650736 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3360/statm: 418 123 108 20 0 45 0
[pid=3361] ppid=3360 vsize=45392 CPUtime=1.26
/proc/3361/stat : 3361 (minisatp_32) R 3360 3353 1511 34817 1511 4202496 12564 0 0 0 108 18 0 0 24 0 1 0 956384 46481408 10147 1283457024 134512640 135413687 4288263264 18446744073709551615 134686446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3361/statm: 11348 10147 94 220 0 11126 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 95728

[startup+12.7068 s]
/proc/loadavg: 1.11 1.04 0.97 2/37 3363
/proc/meminfo: memFree=535556/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=46096 CPUtime=8.07
/proc/3354/stat : 3354 (packup) S 3353 3353 1511 34817 1511 4202496 11327 46667 0 0 189 48 521 49 18 0 1 0 955879 47202304 10864 1283457024 134512640 134752139 4287517408 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3354/statm: 11524 10864 333 59 0 10688 0
[pid=3362] ppid=3354 vsize=1676 CPUtime=0.01
/proc/3362/stat : 3362 (sh) S 3354 3353 1511 34817 1511 4202496 146 0 0 0 0 1 0 0 18 0 1 0 956688 1716224 124 1283457024 134512640 134593992 4292495440 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3362/statm: 419 124 108 20 0 46 0
[pid=3363] ppid=3362 vsize=122024 CPUtime=4.6
/proc/3363/stat : 3363 (minisatp_32) R 3362 3353 1511 34817 1511 4202496 40315 0 0 0 438 22 0 0 25 0 1 0 956688 124952576 26480 1283457024 134512640 135413687 4294435392 18446744073709551615 134686161 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3363/statm: 30506 26480 107 220 0 30284 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 172368

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

[startup+12.9069 s]
/proc/loadavg: 1.11 1.04 0.97 2/37 3363
/proc/meminfo: memFree=535556/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=46096 CPUtime=8.07
/proc/3354/stat : 3354 (packup) S 3353 3353 1511 34817 1511 4202496 11327 46667 0 0 189 48 521 49 18 0 1 0 955879 47202304 10864 1283457024 134512640 134752139 4287517408 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3354/statm: 11524 10864 333 59 0 10688 0
[pid=3362] ppid=3354 vsize=1676 CPUtime=0.01
/proc/3362/stat : 3362 (sh) S 3354 3353 1511 34817 1511 4202496 146 0 0 0 0 1 0 0 18 0 1 0 956688 1716224 124 1283457024 134512640 134593992 4292495440 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3362/statm: 419 124 108 20 0 46 0
[pid=3363] ppid=3362 vsize=124756 CPUtime=4.8
/proc/3363/stat : 3363 (minisatp_32) R 3362 3353 1511 34817 1511 4202496 40448 0 0 0 458 22 0 0 25 0 1 0 956688 127750144 26605 1283457024 134512640 135413687 4294435392 18446744073709551615 134948473 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3363/statm: 31189 26605 107 220 0 30967 0
Current children cumulated CPU time (s) 12.88
Current children cumulated vsize (KiB) 175100

[startup+13.307 s]
/proc/loadavg: 1.11 1.04 0.97 2/37 3363
/proc/meminfo: memFree=532952/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=46096 CPUtime=8.07
/proc/3354/stat : 3354 (packup) S 3353 3353 1511 34817 1511 4202496 11327 46667 0 0 189 48 521 49 18 0 1 0 955879 47202304 10864 1283457024 134512640 134752139 4287517408 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/3354/statm: 11524 10864 333 59 0 10688 0
[pid=3362] ppid=3354 vsize=1676 CPUtime=0.01
/proc/3362/stat : 3362 (sh) S 3354 3353 1511 34817 1511 4202496 146 0 0 0 0 1 0 0 18 0 1 0 956688 1716224 124 1283457024 134512640 134593992 4292495440 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/3362/statm: 419 124 108 20 0 46 0
[pid=3363] ppid=3362 vsize=125500 CPUtime=5.2
/proc/3363/stat : 3363 (minisatp_32) R 3362 3353 1511 34817 1511 4202496 40741 0 0 0 498 22 0 0 25 0 1 0 956688 128512000 26889 1283457024 134512640 135413687 4294435392 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/3363/statm: 31375 26889 110 220 0 31153 0
Current children cumulated CPU time (s) 13.28
Current children cumulated vsize (KiB) 175844

[startup+13.5076 s]
/proc/loadavg: 1.11 1.04 0.97 2/37 3363
/proc/meminfo: memFree=532952/1048576 swapFree=0/0
[pid=3353] ppid=3352 vsize=2572 CPUtime=0
/proc/3353/stat : 3353 (packup2mp4tr-0.) S 3352 3353 1511 34817 1511 4202496 380 0 0 0 0 0 0 0 18 0 1 0 955879 2633728 275 1283457024 134512640 135304128 4292499408 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/3353/statm: 643 275 233 194 0 30 0
[pid=3354] ppid=3353 vsize=46100 CPUtime=13.49
/proc/3354/stat : 3354 (packup) R 3353 3353 1511 34817 1511 4202496 12505 87572 0 0 191 48 1037 73 18 0 1 0 955879 47206400 10878 1283457024 134512640 134752139 4287517408 18446744073709551615 4157430625 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/3354/statm: 11525 10878 346 59 0 10689 0
Current children cumulated CPU time (s) 13.49
Current children cumulated vsize (KiB) 48672

Child status: 0
Real time (s): 13.5989
CPU time (s): 13.5928
CPU user time (s): 12.3568
CPU system time (s): 1.23608
CPU usage (%): 99.9555
Max. virtual memory (cumulated for all children) (KiB): 183148

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.3568
system time used= 1.23608
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 109391
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= 19
involuntary context switches= 235

runsolver used 0 second user time and 0 second system time

The end