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/rand533.cudf.user-upgrades.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/user-upgrades/rand533.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand533.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.28 1.28 1.13 5/35 22078
/proc/meminfo: memFree=334420/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=3976 CPUtime=0.01
/proc/22078/stat : 22078 (packup) R 22077 22077 1511 34817 1511 4202496 489 0 0 0 1 0 0 0 25 0 1 0 4633715 4071424 417 1283457024 134512640 134752139 4292960272 18446744073709551615 134683324 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22078/statm: 994 417 286 59 0 158 0

[startup+0.163338 s]
/proc/loadavg: 1.28 1.28 1.13 5/35 22078
/proc/meminfo: memFree=334420/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=8744 CPUtime=0.15
/proc/22078/stat : 22078 (packup) R 22077 22077 1511 34817 1511 4202496 1672 0 0 0 14 1 0 0 25 0 1 0 4633715 8953856 1600 1283457024 134512640 134752139 4292960272 18446744073709551615 134522732 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22078/statm: 2186 1600 286 59 0 1350 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 11320

[startup+0.213347 s]
/proc/loadavg: 1.28 1.28 1.13 5/35 22078
/proc/meminfo: memFree=334420/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=10196 CPUtime=0.21
/proc/22078/stat : 22078 (packup) R 22077 22077 1511 34817 1511 4202496 2029 0 0 0 20 1 0 0 25 0 1 0 4633715 10440704 1957 1283457024 134512640 134752139 4292960272 18446744073709551615 134681765 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22078/statm: 2549 1957 286 59 0 1713 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12772

[startup+0.303367 s]
/proc/loadavg: 1.28 1.28 1.13 5/35 22078
/proc/meminfo: memFree=334420/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=12464 CPUtime=0.29
/proc/22078/stat : 22078 (packup) R 22077 22077 1511 34817 1511 4202496 2601 0 0 0 28 1 0 0 25 0 1 0 4633715 12763136 2529 1283457024 134512640 134752139 4292960272 18446744073709551615 134706007 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22078/statm: 3116 2529 286 59 0 2280 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 15040

[startup+0.703443 s]
/proc/loadavg: 1.28 1.28 1.13 5/35 22078
/proc/meminfo: memFree=334420/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=21652 CPUtime=0.69
/proc/22078/stat : 22078 (packup) R 22077 22077 1511 34817 1511 4202496 4913 0 0 0 67 2 0 0 25 0 1 0 4633715 22171648 4841 1283457024 134512640 134752139 4292960272 18446744073709551615 134681499 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22078/statm: 5413 4841 286 59 0 4577 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 24228

[startup+1.50361 s]
/proc/loadavg: 1.26 1.28 1.13 2/36 22079
/proc/meminfo: memFree=307872/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=44444 CPUtime=1.5
/proc/22078/stat : 22078 (packup) R 22077 22077 1511 34817 1511 4202496 10690 0 0 0 144 6 0 0 25 0 1 0 4633715 45510656 10569 1283457024 134512640 134752139 4292960272 18446744073709551615 134657868 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22078/statm: 11111 10569 317 59 0 10275 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 47020

[startup+3.10394 s]
/proc/loadavg: 1.26 1.28 1.13 2/38 22081
/proc/meminfo: memFree=279940/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=46072 CPUtime=2.99
/proc/22078/stat : 22078 (packup) S 22077 22077 1511 34817 1511 4202496 11168 8161 0 0 164 28 90 17 18 0 1 0 4633715 47177728 10844 1283457024 134512640 134752139 4292960272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22078/statm: 11518 10844 333 59 0 10682 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 48648

[startup+6.30472 s]
/proc/loadavg: 1.26 1.28 1.13 2/38 22085
/proc/meminfo: memFree=279320/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=46076 CPUtime=5
/proc/22078/stat : 22078 (packup) S 22077 22077 1511 34817 1511 4202496 11248 23414 0 0 171 42 251 36 18 0 1 0 4633715 47181824 10864 1283457024 134512640 134752139 4292960272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22078/statm: 11519 10864 333 59 0 10683 0
[pid=22084] ppid=22078 vsize=1668 CPUtime=0
/proc/22084/stat : 22084 (sh) S 22078 22077 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4634218 1708032 123 1283457024 134512640 134593992 4294236656 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22084/statm: 417 123 108 20 0 44 0
[pid=22085] ppid=22084 vsize=45848 CPUtime=1.27
/proc/22085/stat : 22085 (minisatp_32) R 22084 22077 1511 34817 1511 4202496 13357 0 0 0 115 12 0 0 25 0 1 0 4634218 46948352 10260 1283457024 134512640 135413687 4294539872 18446744073709551615 134649264 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22085/statm: 11462 10260 94 220 0 11240 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 96168

[startup+12.7068 s]
/proc/loadavg: 1.22 1.27 1.12 2/37 22087
/proc/meminfo: memFree=187204/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=46080 CPUtime=8.08
/proc/22078/stat : 22078 (packup) S 22077 22077 1511 34817 1511 4202496 11317 47780 0 0 181 54 519 54 18 0 1 0 4633715 47185920 10865 1283457024 134512640 134752139 4292960272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22078/statm: 11520 10865 333 59 0 10684 0
[pid=22086] ppid=22078 vsize=1668 CPUtime=0
/proc/22086/stat : 22086 (sh) S 22078 22077 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4634525 1708032 123 1283457024 134512640 134593992 4292558928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22086/statm: 417 123 108 20 0 44 0
[pid=22087] ppid=22086 vsize=120768 CPUtime=4.59
/proc/22087/stat : 22087 (minisatp_32) R 22086 22077 1511 34817 1511 4202496 40270 0 0 0 435 24 0 0 25 0 1 0 4634526 123666432 25458 1283457024 134512640 135413687 4287531952 18446744073709551615 134653660 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22087/statm: 30192 25458 107 220 0 29970 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 171092

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

[startup+12.8068 s]
/proc/loadavg: 1.22 1.27 1.12 2/37 22087
/proc/meminfo: memFree=187204/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=46080 CPUtime=8.08
/proc/22078/stat : 22078 (packup) S 22077 22077 1511 34817 1511 4202496 11317 47780 0 0 181 54 519 54 18 0 1 0 4633715 47185920 10865 1283457024 134512640 134752139 4292960272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22078/statm: 11520 10865 333 59 0 10684 0
[pid=22086] ppid=22078 vsize=1668 CPUtime=0
/proc/22086/stat : 22086 (sh) S 22078 22077 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4634525 1708032 123 1283457024 134512640 134593992 4292558928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22086/statm: 417 123 108 20 0 44 0
[pid=22087] ppid=22086 vsize=121232 CPUtime=4.69
/proc/22087/stat : 22087 (minisatp_32) R 22086 22077 1511 34817 1511 4202496 40424 0 0 0 445 24 0 0 25 0 1 0 4634526 124141568 25536 1283457024 134512640 135413687 4287531952 18446744073709551615 134961229 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22087/statm: 30308 25536 107 220 0 30086 0
Current children cumulated CPU time (s) 12.77
Current children cumulated vsize (KiB) 171556

[startup+13.2069 s]
/proc/loadavg: 1.22 1.27 1.12 2/37 22087
/proc/meminfo: memFree=186584/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=46080 CPUtime=8.08
/proc/22078/stat : 22078 (packup) S 22077 22077 1511 34817 1511 4202496 11317 47780 0 0 181 54 519 54 18 0 1 0 4633715 47185920 10865 1283457024 134512640 134752139 4292960272 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22078/statm: 11520 10865 333 59 0 10684 0
[pid=22086] ppid=22078 vsize=1668 CPUtime=0
/proc/22086/stat : 22086 (sh) S 22078 22077 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 18 0 1 0 4634525 1708032 123 1283457024 134512640 134593992 4292558928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22086/statm: 417 123 108 20 0 44 0
[pid=22087] ppid=22086 vsize=121232 CPUtime=5.09
/proc/22087/stat : 22087 (minisatp_32) R 22086 22077 1511 34817 1511 4202496 40886 0 0 0 485 24 0 0 25 0 1 0 4634526 124141568 25818 1283457024 134512640 135413687 4287531952 18446744073709551615 134650451 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22087/statm: 30308 25818 107 220 0 30086 0
Current children cumulated CPU time (s) 13.17
Current children cumulated vsize (KiB) 171556

[startup+13.6069 s]
/proc/loadavg: 1.22 1.27 1.12 2/37 22087
/proc/meminfo: memFree=186584/1048576 swapFree=0/0
[pid=22077] ppid=22076 vsize=2576 CPUtime=0
/proc/22077/stat : 22077 (packup2mp4tr-0.) S 22076 22077 1511 34817 1511 4202496 381 0 0 0 0 0 0 0 25 0 1 0 4633715 2637824 275 1283457024 134512640 135304128 4290020720 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22077/statm: 644 275 233 194 0 31 0
[pid=22078] ppid=22077 vsize=45308 CPUtime=13.58
/proc/22078/stat : 22078 (packup) R 22077 22077 1511 34817 1511 4202496 20109 89053 0 0 183 58 1037 80 18 0 1 0 4633715 46395392 10685 1283457024 134512640 134752139 4292960272 18446744073709551615 4159131794 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22078/statm: 11327 10685 346 59 0 10491 0
Current children cumulated CPU time (s) 13.58
Current children cumulated vsize (KiB) 47884

Child status: 0
Real time (s): 13.6557
CPU time (s): 13.6369
CPU user time (s): 12.2448
CPU system time (s): 1.39209
CPU usage (%): 99.8617
Max. virtual memory (cumulated for all children) (KiB): 178196

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.2448
system time used= 1.39209
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 110862
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= 227

runsolver used 0.008 second user time and 0 second system time

The end