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/randd8bf6a.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//randd8bf6a.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/randd8bf6a.cudf.difficult.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.08 1.02 2/41 5704
/proc/meminfo: memFree=755008/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2580 CPUtime=0
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 517 1357 0 0 0 0 0 0 25 0 1 0 885444274 2641920 280 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 645 280 237 194 0 31 0
[pid=5704] ppid=5696 vsize=2004 CPUtime=0
/proc/5704/stat : 5704 (cp) R 5696 5696 4159 34819 4229 4202496 254 0 0 0 0 0 0 0 25 0 1 0 885444275 2052096 183 1283457024 134512640 134614052 4290446944 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/5704/statm: 501 183 145 25 0 47 0

[startup+0.169912 s]
/proc/loadavg: 1.28 1.08 1.02 2/41 5704
/proc/meminfo: memFree=755008/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2580 CPUtime=0.02
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 566 1858 0 0 0 0 0 2 25 0 1 0 885444274 2641920 283 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.209923 s]
/proc/loadavg: 1.28 1.08 1.02 2/41 5704
/proc/meminfo: memFree=755008/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2580 CPUtime=0.02
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 566 1858 0 0 0 0 0 2 25 0 1 0 885444274 2641920 283 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.310032 s]
/proc/loadavg: 1.28 1.08 1.02 2/41 5704
/proc/meminfo: memFree=755008/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2580 CPUtime=0.02
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 566 1858 0 0 0 0 0 2 25 0 1 0 885444274 2641920 283 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.710111 s]
/proc/loadavg: 1.28 1.08 1.02 2/41 5704
/proc/meminfo: memFree=755008/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2580 CPUtime=0.02
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 566 1858 0 0 0 0 0 2 25 0 1 0 885444274 2641920 283 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+1.51024 s]
/proc/loadavg: 1.26 1.08 1.02 2/42 5707
/proc/meminfo: memFree=719840/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2580 CPUtime=0.02
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 566 1858 0 0 0 0 0 2 25 0 1 0 885444274 2641920 283 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 645 283 240 194 0 31 0
[pid=5707] ppid=5696 vsize=33256 CPUtime=1.48
/proc/5707/stat : 5707 (cudftodeb.nativ) R 5696 5696 4159 34819 4229 4202496 7873 0 0 0 148 0 0 0 25 0 1 0 885444278 34054144 7800 1283457024 134512640 135004320 4294113696 18446744073709551615 134986312 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5707/statm: 8314 7800 225 121 0 7706 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 35836

[startup+3.11048 s]
/proc/loadavg: 1.26 1.08 1.02 2/42 5707
/proc/meminfo: memFree=697396/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2580 CPUtime=0.02
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 566 1858 0 0 0 0 0 2 25 0 1 0 885444274 2641920 283 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 645 283 240 194 0 31 0
[pid=5707] ppid=5696 vsize=68360 CPUtime=3.08
/proc/5707/stat : 5707 (cudftodeb.nativ) R 5696 5696 4159 34819 4229 4202496 16496 0 0 0 306 2 0 0 25 0 1 0 885444278 70000640 16423 1283457024 134512640 135004320 4294113696 18446744073709551615 134527461 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5707/statm: 17090 16423 237 121 0 16482 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 70940

[startup+6.30593 s]
/proc/loadavg: 1.26 1.08 1.02 2/42 5707
/proc/meminfo: memFree=638876/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=5.6
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 650 25900 0 0 0 0 547 13 18 0 1 0 885444274 2650112 286 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 286 241 194 0 33 0
Current children cumulated CPU time (s) 5.6
Current children cumulated vsize (KiB) 2588

[startup+12.7135 s]
/proc/loadavg: 1.29 1.09 1.02 2/43 5721
/proc/meminfo: memFree=656796/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=5.83
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 694 28294 0 1 0 0 567 16 18 0 1 0 885444274 2650112 294 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 294 249 194 0 33 0
[pid=5717] ppid=5696 vsize=63508 CPUtime=5
/proc/5717/stat : 5717 (aptitude) R 5696 5696 4159 34819 4229 4202496 16785 649 267 0 444 56 0 0 25 0 2 0 885444922 65032192 10387 1283457024 134512640 137933492 4287565440 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/5717/statm: 15877 10387 5967 836 0 8509 0
[pid=5717/tid=5719] ppid=5696 vsize=63508 CPUtime=0.44
/proc/5717/task/5719/stat : 5719 (aptitude) R 5696 5696 4159 34819 4229 4202560 1935 649 0 0 42 2 0 0 16 0 2 0 885445174 65032192 10387 1283457024 134512640 137933492 4287565440 18446744073709551615 4160427015 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.83
Current children cumulated vsize (KiB) 66096

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

[startup+12.8035 s]
/proc/loadavg: 1.29 1.09 1.02 2/43 5721
/proc/meminfo: memFree=656796/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=5.83
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 694 28294 0 1 0 0 567 16 18 0 1 0 885444274 2650112 294 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 294 249 194 0 33 0
[pid=5717] ppid=5696 vsize=64036 CPUtime=5.09
/proc/5717/stat : 5717 (aptitude) R 5696 5696 4159 34819 4229 4202496 16966 649 267 0 453 56 0 0 25 0 2 0 885444922 65572864 10562 1283457024 134512640 137933492 4287565440 18446744073709551615 4153964093 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/5717/statm: 16009 10562 6003 836 0 8641 0
[pid=5717/tid=5719] ppid=5696 vsize=64036 CPUtime=0.5
/proc/5717/task/5719/stat : 5719 (aptitude) S 5696 5696 4159 34819 4229 4202560 2042 649 0 0 48 2 0 0 16 0 2 0 885445174 65572864 10562 1283457024 134512640 137933492 4287565440 18446744073709551615 4294960130 0 134217728 4096 0 18446612132549438336 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.92
Current children cumulated vsize (KiB) 66624

[startup+14.4136 s]
/proc/loadavg: 1.29 1.09 1.02 2/42 5723
/proc/meminfo: memFree=652472/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=11.56
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 721 48125 0 268 0 0 1083 73 18 0 1 0 885444274 2650112 294 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 294 249 194 0 33 0
[pid=5723] ppid=5696 vsize=22544 CPUtime=0.89
/proc/5723/stat : 5723 (aptsolutions.na) R 5696 5696 4159 34819 4229 4202496 5245 0 0 0 88 1 0 0 23 0 1 0 885445624 23085056 5133 1283457024 134512640 134971616 4291235520 18446744073709551615 134954228 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5723/statm: 5636 5133 204 113 0 5038 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 25132

[startup+15.2137 s]
/proc/loadavg: 1.29 1.09 1.02 2/42 5723
/proc/meminfo: memFree=652472/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=11.56
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 721 48125 0 268 0 0 1083 73 18 0 1 0 885444274 2650112 294 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 294 249 194 0 33 0
[pid=5723] ppid=5696 vsize=39040 CPUtime=1.69
/proc/5723/stat : 5723 (aptsolutions.na) R 5696 5696 4159 34819 4229 4202496 9322 0 0 0 168 1 0 0 25 0 1 0 885445624 39976960 9210 1283457024 134512640 134971616 4291235520 18446744073709551615 134928406 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5723/statm: 9760 9210 204 113 0 9162 0
Current children cumulated CPU time (s) 13.25
Current children cumulated vsize (KiB) 41628

[startup+15.6138 s]
/proc/loadavg: 1.29 1.09 1.02 2/42 5723
/proc/meminfo: memFree=629160/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=11.56
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 721 48125 0 268 0 0 1083 73 18 0 1 0 885444274 2650112 294 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 294 249 194 0 33 0
[pid=5723] ppid=5696 vsize=46976 CPUtime=2.09
/proc/5723/stat : 5723 (aptsolutions.na) R 5696 5696 4159 34819 4229 4202496 11223 0 0 0 208 1 0 0 25 0 1 0 885445624 48103424 11111 1283457024 134512640 134971616 4291235520 18446744073709551615 134915762 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5723/statm: 11744 11111 204 113 0 11146 0
Current children cumulated CPU time (s) 13.65
Current children cumulated vsize (KiB) 49564

[startup+15.8139 s]
/proc/loadavg: 1.29 1.09 1.02 2/42 5723
/proc/meminfo: memFree=629160/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=11.56
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 721 48125 0 268 0 0 1083 73 18 0 1 0 885444274 2650112 294 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 294 249 194 0 33 0
[pid=5723] ppid=5696 vsize=51192 CPUtime=2.29
/proc/5723/stat : 5723 (aptsolutions.na) R 5696 5696 4159 34819 4229 4202496 12307 0 0 0 228 1 0 0 25 0 1 0 885445624 52420608 12195 1283457024 134512640 134971616 4291235520 18446744073709551615 134625573 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5723/statm: 12798 12195 204 113 0 12200 0
Current children cumulated CPU time (s) 13.85
Current children cumulated vsize (KiB) 53780

[startup+15.9039 s]
/proc/loadavg: 1.29 1.09 1.02 2/42 5723
/proc/meminfo: memFree=629160/1048576 swapFree=2077620/2097144
[pid=5696] ppid=5695 vsize=2588 CPUtime=11.56
/proc/5696/stat : 5696 (aptitude-trendy) S 5695 5696 4159 34819 4229 4202496 721 48125 0 268 0 0 1083 73 18 0 1 0 885444274 2650112 294 1283457024 134512640 135304128 4294490544 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5696/statm: 647 294 249 194 0 33 0
[pid=5723] ppid=5696 vsize=54048 CPUtime=2.38
/proc/5723/stat : 5723 (aptsolutions.na) R 5696 5696 4159 34819 4229 4202496 13038 0 0 0 237 1 0 0 25 0 1 0 885445624 55345152 12926 1283457024 134512640 134971616 4291235520 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5723/statm: 13512 12926 208 113 0 12914 0
Current children cumulated CPU time (s) 13.94
Current children cumulated vsize (KiB) 56636

Child status: 0
Real time (s): 15.991
CPU time (s): 14.0329
CPU user time (s): 13.2888
CPU system time (s): 0.744046
CPU usage (%): 87.7547
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.2888
system time used= 0.744046
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 63046
page faults= 268
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 311
involuntary context switches= 379

runsolver used 0 second user time and 0 second system time

The end