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/201012070034/apt-get-trendy-1.0/rand6b4d6e.cudf.impossible.log.runsolver ./apt-get-trendy-1.0 /home/misc2010/data/2010/impossible//rand6b4d6e.cudf /home/misc2010/tmp/201012070034/apt-get-trendy-1.0/rand6b4d6e.cudf.impossible.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.06 1.03 1.00 5/41 16728
/proc/meminfo: memFree=783920/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 508 1359 0 0 0 0 0 0 25 0 1 0 880604363 2641920 279 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 279 237 194 0 31 0

[startup+0.20443 s]
/proc/loadavg: 1.06 1.03 1.00 5/41 16728
/proc/meminfo: memFree=783920/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 508 1359 0 0 0 0 0 0 25 0 1 0 880604363 2641920 279 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 279 237 194 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2580

[startup+0.304445 s]
/proc/loadavg: 1.06 1.03 1.00 5/41 16728
/proc/meminfo: memFree=783920/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 508 1359 0 0 0 0 0 0 25 0 1 0 880604363 2641920 279 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 279 237 194 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2580

[startup+0.447565 s]
/proc/loadavg: 1.06 1.03 1.00 5/41 16728
/proc/meminfo: memFree=783920/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0.02
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 555 1857 0 0 0 0 0 2 22 0 1 0 880604363 2641920 282 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.707564 s]
/proc/loadavg: 1.06 1.03 1.00 5/41 16728
/proc/meminfo: memFree=783920/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0.02
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 555 1857 0 0 0 0 0 2 22 0 1 0 880604363 2641920 282 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+1.50779 s]
/proc/loadavg: 1.06 1.03 1.00 2/42 16738
/proc/meminfo: memFree=712496/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0.02
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 555 1857 0 0 0 0 0 2 22 0 1 0 880604363 2641920 282 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 282 240 194 0 31 0
[pid=16738] ppid=16727 vsize=26808 CPUtime=1.11
/proc/16738/stat : 16738 (cudftodeb.nativ) R 16727 16727 4159 34819 4229 4202496 6304 0 0 0 108 3 0 0 25 0 1 0 880604401 27451392 6231 1283457024 134512640 135004320 4294136224 18446744073709551615 134949961 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16738/statm: 6702 6231 225 121 0 6094 0
Current children cumulated CPU time (s) 1.13
Current children cumulated vsize (KiB) 29388

[startup+3.10821 s]
/proc/loadavg: 1.06 1.03 1.00 2/42 16738
/proc/meminfo: memFree=689680/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0.02
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 555 1857 0 0 0 0 0 2 22 0 1 0 880604363 2641920 282 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 282 240 194 0 31 0
[pid=16738] ppid=16727 vsize=59424 CPUtime=2.71
/proc/16738/stat : 16738 (cudftodeb.nativ) R 16727 16727 4159 34819 4229 4202496 14327 0 0 0 264 7 0 0 25 0 1 0 880604401 60850176 14254 1283457024 134512640 135004320 4294136224 18446744073709551615 134607703 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16738/statm: 14856 14254 225 121 0 14248 0
Current children cumulated CPU time (s) 2.73
Current children cumulated vsize (KiB) 62004

[startup+6.30911 s]
/proc/loadavg: 1.06 1.03 1.00 2/42 16738
/proc/meminfo: memFree=631780/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0.02
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 555 1857 0 0 0 0 0 2 22 0 1 0 880604363 2641920 282 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 282 240 194 0 31 0
[pid=16738] ppid=16727 vsize=116920 CPUtime=5.9
/proc/16738/stat : 16738 (cudftodeb.nativ) R 16727 16727 4159 34819 4229 4202496 28413 0 0 0 578 12 0 0 25 0 1 0 880604401 119726080 28340 1283457024 134512640 135004320 4294136224 18446744073709551615 134530092 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16738/statm: 29230 28340 236 121 0 28622 0
Current children cumulated CPU time (s) 5.92
Current children cumulated vsize (KiB) 119500

[startup+12.7112 s]
/proc/loadavg: 1.05 1.03 1.00 2/42 16738
/proc/meminfo: memFree=537416/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0.02
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 555 1857 0 0 0 0 0 2 22 0 1 0 880604363 2641920 282 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 282 240 194 0 31 0
[pid=16738] ppid=16727 vsize=181256 CPUtime=12.3
/proc/16738/stat : 16738 (cudftodeb.nativ) R 16727 16727 4159 34819 4229 4202496 44296 0 0 0 1200 30 0 0 25 0 1 0 880604401 185606144 44223 1283457024 134512640 135004320 4294136224 18446744073709551615 134990466 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16738/statm: 45314 44223 237 121 0 44706 0
Current children cumulated CPU time (s) 12.32
Current children cumulated vsize (KiB) 183836

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

[startup+12.9112 s]
/proc/loadavg: 1.05 1.03 1.00 2/42 16738
/proc/meminfo: memFree=537416/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2580 CPUtime=0.02
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 555 1857 0 0 0 0 0 2 22 0 1 0 880604363 2641920 282 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 645 282 240 194 0 31 0
[pid=16738] ppid=16727 vsize=97184 CPUtime=12.5
/proc/16738/stat : 16738 (cudftodeb.nativ) R 16727 16727 4159 34819 4229 4202496 44296 0 0 0 1217 33 0 0 25 0 1 0 880604401 99516416 23544 1283457024 134512640 135004320 4294136224 18446744073709551615 134943981 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16738/statm: 24296 23544 237 121 0 23688 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 99764

[startup+16.112 s]
/proc/loadavg: 1.05 1.03 1.00 2/42 16746
/proc/meminfo: memFree=660056/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2588 CPUtime=14.01
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 688 49444 0 1 0 0 1355 46 18 0 1 0 880604363 2650112 293 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 647 293 249 194 0 33 0
Current children cumulated CPU time (s) 14.01
Current children cumulated vsize (KiB) 2588

[startup+17.7016 s]
/proc/loadavg: 1.04 1.03 1.00 1/42 16748
/proc/meminfo: memFree=583744/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2588 CPUtime=14.01
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 688 49444 0 1 0 0 1355 46 18 0 1 0 880604363 2650112 293 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 647 293 249 194 0 33 0
[pid=16748] ppid=16727 vsize=101452 CPUtime=2.03
/proc/16748/stat : 16748 (apt-get) D 16727 16727 4159 34819 4229 4202496 9309 0 532 0 190 13 0 0 25 0 1 0 880605921 103886848 9766 1283457024 134512640 134619611 4289171728 18446744073709551615 4294960130 0 0 4096 134217728 18446744071564332537 0 0 17 0 0 0 0
/proc/16748/statm: 25363 9766 9713 27 0 57 0
Current children cumulated CPU time (s) 16.04
Current children cumulated vsize (KiB) 104040

[startup+19.3056 s]
/proc/loadavg: 1.04 1.03 1.00 1/42 16748
/proc/meminfo: memFree=583752/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2588 CPUtime=14.01
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 688 49444 0 1 0 0 1355 46 18 0 1 0 880604363 2650112 293 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 647 293 249 194 0 33 0
[pid=16748] ppid=16727 vsize=44072 CPUtime=2.1
/proc/16748/stat : 16748 (apt-get) R 16727 16727 4159 34819 4229 4202496 11217 0 535 0 192 18 0 0 18 0 1 0 880605921 45129728 2262 1283457024 134512640 134619611 4289171728 18446744073709551615 4160135849 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/16748/statm: 11018 2262 1561 27 0 705 0
Current children cumulated CPU time (s) 16.11
Current children cumulated vsize (KiB) 46660

[startup+19.7106 s]
/proc/loadavg: 1.04 1.03 1.00 1/42 16748
/proc/meminfo: memFree=583752/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2588 CPUtime=14.01
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 688 49444 0 1 0 0 1355 46 18 0 1 0 880604363 2650112 293 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 647 293 249 194 0 33 0
[pid=16748] ppid=16727 vsize=44408 CPUtime=2.5
/proc/16748/stat : 16748 (apt-get) R 16727 16727 4159 34819 4229 4202496 19058 0 535 0 231 19 0 0 18 0 1 0 880605921 45473792 10053 1283457024 134512640 134619611 4289171728 18446744073709551615 4159864431 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/16748/statm: 11102 10053 9289 27 0 789 0
Current children cumulated CPU time (s) 16.51
Current children cumulated vsize (KiB) 46996

[startup+19.9106 s]
/proc/loadavg: 1.04 1.03 1.00 2/42 16748
/proc/meminfo: memFree=580280/1048576 swapFree=2080296/2097144
[pid=16727] ppid=16726 vsize=2588 CPUtime=14.01
/proc/16727/stat : 16727 (apt-get-trendy-) S 16726 16727 4159 34819 4229 4202496 688 49444 0 1 0 0 1355 46 18 0 1 0 880604363 2650112 293 1283457024 134512640 135304128 4293607632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16727/statm: 647 293 249 194 0 33 0
[pid=16748] ppid=16727 vsize=44408 CPUtime=2.7
/proc/16748/stat : 16748 (apt-get) R 16727 16727 4159 34819 4229 4202496 19058 0 535 0 251 19 0 0 18 0 1 0 880605921 45473792 10053 1283457024 134512640 134619611 4289171728 18446744073709551615 4159967508 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/16748/statm: 11102 10053 9289 27 0 789 0
Current children cumulated CPU time (s) 16.71
Current children cumulated vsize (KiB) 46996

Child status: 100
Real time (s): 20.005
CPU time (s): 16.8291
CPU user time (s): 16.153
CPU system time (s): 0.676042
CPU usage (%): 84.1243
Max. virtual memory (cumulated for all children) (KiB): 183836

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 16.153
system time used= 0.676042
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 69209
page faults= 536
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 549
involuntary context switches= 345

runsolver used 0 second user time and 0.012 second system time

The end