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/aptitude-trendy-1.0/rand5c1800.cudf.easy.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/easy//rand5c1800.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand5c1800.cudf.easy.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: 0.89 0.99 1.04 1/46 21667
/proc/meminfo: memFree=850740/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=3020 CPUtime=0
/proc/21667/stat : 21667 (runsolver) D 21666 21667 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 881857439 3092480 93 1283457024 134512640 134586868 4291350000 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/21667/statm: 755 93 62 19 0 53 0

[startup+0.206925 s]
/proc/loadavg: 0.89 0.99 1.04 1/46 21667
/proc/meminfo: memFree=850740/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2588 CPUtime=0.02
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 567 1866 0 0 0 0 0 2 25 0 1 0 881857439 2650112 284 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.306945 s]
/proc/loadavg: 0.89 0.99 1.04 1/46 21667
/proc/meminfo: memFree=850740/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2588 CPUtime=0.02
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 567 1866 0 0 0 0 0 2 25 0 1 0 881857439 2650112 284 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.406973 s]
/proc/loadavg: 0.89 0.99 1.04 1/46 21667
/proc/meminfo: memFree=850740/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2588 CPUtime=0.02
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 567 1866 0 0 0 0 0 2 25 0 1 0 881857439 2650112 284 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.707014 s]
/proc/loadavg: 0.89 0.99 1.04 1/46 21667
/proc/meminfo: memFree=850740/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2588 CPUtime=0.02
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 567 1866 0 0 0 0 0 2 25 0 1 0 881857439 2650112 284 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+1.50718 s]
/proc/loadavg: 0.89 0.99 1.04 2/48 21678
/proc/meminfo: memFree=816416/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2588 CPUtime=0.02
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 567 1866 0 0 0 0 0 2 25 0 1 0 881857439 2650112 284 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 647 284 240 194 0 33 0
[pid=21678] ppid=21667 vsize=33436 CPUtime=1.45
/proc/21678/stat : 21678 (cudftodeb.nativ) R 21667 21667 4159 34819 4229 4202496 7933 0 8 0 143 2 0 0 25 0 1 0 881857442 34238464 7867 1283457024 134512640 135004320 4287205968 18446744073709551615 134948038 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21678/statm: 8359 7867 225 121 0 7751 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 36024

[startup+3.10752 s]
/proc/loadavg: 0.90 0.99 1.04 2/48 21678
/proc/meminfo: memFree=790996/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2588 CPUtime=0.02
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 567 1866 0 0 0 0 0 2 25 0 1 0 881857439 2650112 284 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 647 284 240 194 0 33 0
[pid=21678] ppid=21667 vsize=31476 CPUtime=3.05
/proc/21678/stat : 21678 (cudftodeb.nativ) R 21667 21667 4159 34819 4229 4202496 12305 0 8 0 300 5 0 0 25 0 1 0 881857442 32231424 7420 1283457024 134512640 135004320 4287205968 18446744073709551615 134855897 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21678/statm: 7869 7420 237 121 0 7261 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 34064

[startup+6.30719 s]
/proc/loadavg: 0.90 0.99 1.04 1/48 21689
/proc/meminfo: memFree=789408/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2596 CPUtime=3.43
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 693 18009 0 9 0 0 332 11 18 0 1 0 881857439 2658304 295 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 649 295 249 194 0 35 0
[pid=21688] ppid=21667 vsize=29332 CPUtime=0.72
/proc/21688/stat : 21688 (aptitude) R 21667 21667 4159 34819 4229 4202496 8526 239 241 0 70 2 0 0 18 0 1 0 881857867 30035968 5438 1283457024 134512640 137933492 4289944832 18446744073709551615 135843022 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/21688/statm: 7333 5438 3856 836 0 1549 0
Current children cumulated CPU time (s) 4.15
Current children cumulated vsize (KiB) 31928
heavy processes:

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

[startup+6.50721 s]
/proc/loadavg: 0.90 0.99 1.04 2/48 21689
/proc/meminfo: memFree=780088/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2596 CPUtime=3.43
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 693 18009 0 9 0 0 332 11 18 0 1 0 881857439 2658304 295 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 649 295 249 194 0 35 0
[pid=21688] ppid=21667 vsize=31248 CPUtime=0.8
/proc/21688/stat : 21688 (aptitude) D 21667 21667 4159 34819 4229 4202496 9128 239 241 0 78 2 0 0 18 0 1 0 881857867 31997952 5801 1283457024 134512640 137933492 4289944832 18446744073709551615 4294960130 0 134217728 4096 0 18446744071564332000 0 0 17 0 0 0 0
/proc/21688/statm: 7812 5801 3862 836 0 2028 0
Current children cumulated CPU time (s) 4.23
Current children cumulated vsize (KiB) 33844

[startup+9.71074 s]
/proc/loadavg: 0.91 0.99 1.03 2/49 21692
/proc/meminfo: memFree=775212/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2596 CPUtime=6.98
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 721 31773 0 270 0 0 630 68 18 0 1 0 881857439 2658304 295 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 649 295 249 194 0 35 0
Current children cumulated CPU time (s) 6.98
Current children cumulated vsize (KiB) 2596

[startup+10.511 s]
/proc/loadavg: 0.91 0.99 1.03 2/48 21694
/proc/meminfo: memFree=773820/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2596 CPUtime=6.98
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 721 31773 0 270 0 0 630 68 18 0 1 0 881857439 2658304 295 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 649 295 249 194 0 35 0
[pid=21694] ppid=21667 vsize=23968 CPUtime=1
/proc/21694/stat : 21694 (aptsolutions.na) R 21667 21667 4159 34819 4229 4202496 5603 0 9 0 98 2 0 0 24 0 1 0 881858385 24543232 5499 1283457024 134512640 134971616 4294451664 18446744073709551615 134954115 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21694/statm: 5992 5499 204 113 0 5394 0
Current children cumulated CPU time (s) 7.98
Current children cumulated vsize (KiB) 26564

[startup+10.9111 s]
/proc/loadavg: 0.91 0.99 1.03 2/48 21694
/proc/meminfo: memFree=773820/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2596 CPUtime=6.98
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 721 31773 0 270 0 0 630 68 18 0 1 0 881857439 2658304 295 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 649 295 249 194 0 35 0
[pid=21694] ppid=21667 vsize=32152 CPUtime=1.4
/proc/21694/stat : 21694 (aptsolutions.na) R 21667 21667 4159 34819 4229 4202496 7648 0 9 0 137 3 0 0 25 0 1 0 881858385 32923648 7544 1283457024 134512640 134971616 4294451664 18446744073709551615 134912812 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21694/statm: 8038 7544 204 113 0 7440 0
Current children cumulated CPU time (s) 8.38
Current children cumulated vsize (KiB) 34748

[startup+11.1112 s]
/proc/loadavg: 0.91 0.99 1.03 2/48 21694
/proc/meminfo: memFree=747656/1048576 swapFree=2072372/2097144
[pid=21667] ppid=21666 vsize=2596 CPUtime=6.98
/proc/21667/stat : 21667 (aptitude-trendy) S 21666 21667 4159 34819 4229 4202496 721 31773 0 270 0 0 630 68 18 0 1 0 881857439 2658304 295 1283457024 134512640 135304128 4289410272 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21667/statm: 649 295 249 194 0 35 0
[pid=21694] ppid=21667 vsize=40064 CPUtime=1.6
/proc/21694/stat : 21694 (aptsolutions.na) R 21667 21667 4159 34819 4229 4202496 9578 0 9 0 157 3 0 0 25 0 1 0 881858385 41025536 9472 1283457024 134512640 134971616 4294451664 18446744073709551615 134917058 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21694/statm: 10016 9472 209 113 0 9418 0
Current children cumulated CPU time (s) 8.58
Current children cumulated vsize (KiB) 42660

Child status: 0
Real time (s): 11.2049
CPU time (s): 8.68054
CPU user time (s): 7.9525
CPU system time (s): 0.728045
CPU usage (%): 77.4708
Max. virtual memory (cumulated for all children) (KiB): 111008

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.9525
system time used= 0.728045
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43860
page faults= 279
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 398
involuntary context switches= 233

runsolver used 0.004 second user time and 0 second system time

The end