Kann mir jemand dieses Verhalten des GC erklären?

[Jaiel]

hey hier mein logcat von meiner app während sie läuft:

03-26 17:56:09.279: D/dalvikvm(580): GC_FOR_ALLOC freed 359K, 18% free 7316K/8839K, paused 46ms
03-26 17:56:09.399: D/dalvikvm(580): GC_FOR_ALLOC freed 273K, 18% free 7315K/8839K, paused 43ms
03-26 17:56:09.569: D/dalvikvm(580): GC_FOR_ALLOC freed 261K, 18% free 7315K/8839K, paused 42ms
03-26 17:56:09.669: D/dalvikvm(580): GC_FOR_ALLOC freed 271K, 18% free 7310K/8839K, paused 46ms
03-26 17:56:09.809: D/dalvikvm(580): GC_FOR_ALLOC freed 261K, 18% free 7314K/8839K, paused 44ms
03-26 17:56:09.939: D/dalvikvm(580): GC_FOR_ALLOC freed 266K, 18% free 7316K/8839K, paused 43ms
03-26 17:56:10.079: D/dalvikvm(580): GC_FOR_ALLOC freed 265K, 18% free 7315K/8839K, paused 44ms
03-26 17:56:10.219: D/dalvikvm(580): GC_FOR_ALLOC freed 261K, 18% free 7317K/8839K, paused 43ms
03-26 17:56:10.329: D/dalvikvm(580): GC_FOR_ALLOC freed 269K, 18% free 7316K/8839K, paused 39ms
03-26 17:56:10.449: D/dalvikvm(580): GC_FOR_ALLOC freed 263K, 18% free 7314K/8839K, paused 44ms
03-26 17:56:10.588: D/dalvikvm(580): GC_FOR_ALLOC freed 263K, 18% free 7318K/8839K, paused 43ms
03-26 17:56:10.729: D/dalvikvm(580): GC_FOR_ALLOC freed 268K, 18% free 7314K/8839K, paused 42ms
03-26 17:56:10.849: D/dalvikvm(580): GC_FOR_ALLOC freed 267K, 18% free 7308K/8839K, paused 43ms
03-26 17:56:10.959: D/dalvikvm(580): GC_FOR_ALLOC freed 264K, 18% free 7312K/8839K, paused 39ms
03-26 17:56:11.079: D/dalvikvm(580): GC_FOR_ALLOC freed 261K, 18% free 7314K/8839K, paused 44ms
03-26 17:56:11.209: D/dalvikvm(580): GC_FOR_ALLOC freed 268K, 18% free 7309K/8839K, paused 44ms
03-26 17:56:11.349: D/dalvikvm(580): GC_FOR_ALLOC freed 263K, 18% free 7314K/8839K, paused 44ms
03-26 17:56:11.469: D/dalvikvm(580): GC_FOR_ALLOC freed 261K, 18% free 7319K/8839K, paused 39ms
03-26 17:56:11.569: D/dalvikvm(580): GC_FOR_ALLOC freed 263K, 18% free 7322K/8839K, paused 44ms
03-26 17:56:11.699: D/dalvikvm(580): GC_FOR_ALLOC freed 269K, 18% free 7314K/8839K, paused 45ms
03-26 17:56:11.819: D/dalvikvm(580): GC_FOR_ALLOC freed 265K, 18% free 7312K/8839K, paused 43ms
03-26 17:56:11.949: D/dalvikvm(580): GC_FOR_ALLOC freed 266K, 18% free 7314K/8839K, paused 43ms
03-26 17:56:12.049: D/dalvikvm(580): GC_FOR_ALLOC freed 262K, 18% free 7312K/8839K, paused 39ms
03-26 17:56:12.139: D/dalvikvm(580): GC_FOR_ALLOC freed 269K, 18% free 7309K/8839K, paused 39ms
03-26 17:56:12.239: D/dalvikvm(580): GC_FOR_ALLOC freed 261K, 18% free 7314K/8839K, paused 40ms
03-26 17:56:12.339: D/dalvikvm(580): GC_FOR_ALLOC freed 265K, 18% free 7314K/8839K, paused 43ms
03-26 17:56:12.469: D/dalvikvm(580): GC_FOR_ALLOC freed 276K, 18% free 7304K/8839K, paused 44ms
03-26 17:56:12.599: D/dalvikvm(580): GC_FOR_ALLOC freed 265K, 18% free 7308K/8839K, paused 43ms
03-26 17:56:12.729: D/dalvikvm(580): GC_FOR_ALLOC freed 267K, 18% free 7304K/8839K, paused 43ms
03-26 17:56:12.819: D/dalvikvm(580): GC_FOR_ALLOC freed 260K, 18% free 7307K/8839K, paused 39ms
03-26 17:56:12.909: D/dalvikvm(580): GC_FOR_ALLOC freed 269K, 18% free 7304K/8839K, paused 39ms
03-26 17:56:13.029: D/dalvikvm(580): GC_FOR_ALLOC freed 262K, 18% free 7303K/8839K, paused 43ms
03-26 17:56:13.138: D/dalvikvm(580): GC_FOR_ALLOC freed 264K, 18% free 7302K/8839K, paused 43ms
03-26 17:56:13.279: D/dalvikvm(580): GC_FOR_ALLOC freed 267K, 18% free 7303K/8839K, paused 44ms
03-26 17:56:13.388: D/dalvikvm(580): GC_FOR_ALLOC freed 263K, 18% free 7300K/8839K, paused 40ms
03-26 17:56:13.479: D/dalvikvm(580): GC_FOR_ALLOC freed 267K, 18% free 7301K/8839K, paused 43ms
03-26 17:56:13.588: D/dalvikvm(580): GC_FOR_ALLOC freed 261K, 18% free 7303K/8839K, paused 40ms
03-26 17:56:13.689: D/dalvikvm(580): GC_FOR_ALLOC freed 269K, 18% free 7302K/8839K, paused 43ms
03-26 17:56:13.819: D/dalvikvm(580): GC_FOR_ALLOC freed 263K, 18% free 7303K/8839K, paused 44ms
03-26 17:56:13.938: D/dalvikvm(580): GC_FOR_ALLOC freed 268K, 18% free 7308K/8839K, paused 39ms
03-26 17:56:14.038: D/dalvikvm(580): GC_FOR_ALLOC freed 263K, 18% free 7305K/8839K, paused 41ms
03-26 17:56:14.129: D/dalvikvm(580): GC_FOR_ALLOC freed 260K, 18% free 7306K/8839K, paused 39ms
03-26 17:56:14.229: D/dalvikvm(580): GC_FOR_ALLOC freed 272K, 18% free 7303K/8839K, paused 40ms
03-26 17:56:14.319: D/dalvikvm(580): GC_FOR_ALLOC freed 262K, 18% free 7302K/8839K, paused 39ms
03-26 17:56:19.688: D/dalvikvm(171): GC_CONCURRENT freed 385K, 8% free 6973K/7559K, paused 5ms+5ms
03-26 17:56:24.568: D/dalvikvm(580): GC_CONCURRENT freed 381K, 18% free 7305K/8839K, paused 4ms+4ms
03-26 17:56:59.359: D/dalvikvm(580): GC_CONCURRENT freed 384K, 18% free 7305K/8839K, paused 4ms+4ms
03-26 17:57:33.838: D/dalvikvm(580): GC_CONCURRENT freed 384K, 18% free 7306K/8839K, paused 4ms+10ms
03-26 17:58:08.298: D/dalvikvm(580): GC_CONCURRENT freed 385K, 18% free 7305K/8839K, paused 5ms+11ms
03-26 17:58:42.569: D/dalvikvm(580): GC_CONCURRENT freed 384K, 18% free 7305K/8839K, paused 4ms+3ms

ok die free for alloc kommen daher weil ich mein menu ein bisschen gescrollt habe und dort werden dann bitmaps neu created und alte überschrieben(der menüeintrag der zur auswahl steht oder in die nähe der auswahl gezogen wird wird immer größer und ja ich weiß 30-40 ms ist viel aber die bitmaps liegen ZUR ZEIT in 256x256 vor und der pc ist nciht der schnellste) das heißt dort räumt er die alten leichen der bitmaps auf

nur versteh ich nciht wieso er sich ca alle 30 sekunden wieder zu wort meldet mit gc_concurrent obwohl ncihts passiert keine objekte zerstört werden ncihts.... trotzdem tut der GC irgendwelche arbeit...sind da irgendwelche bösen mächte am werk ^^
oder sind das performance sachen die er macht???

 

[missspelled]

Eine Antwort dazu würde mich auch brennend interessieren.
Aus dem reinen Menschenverstand würde ich sagen, dass das System nach einer gewissen Zeit automatisch Objekte zerstört, wenn sie nicht gebraucht werden. Aber "glauben" tut man ja bekanntlich in der Kirche

 

[Jaiel]

also hier nochmal ein update mit der version wo ich als ressourcen 128x128 png's nutze

03-26 22:16:17.040: D/dalvikvm(628): GC_CONCURRENT freed 368K, 16% free 7433K/8839K, paused 5ms+13ms
03-26 22:16:17.380: D/dalvikvm(628): GC_CONCURRENT freed 517K, 16% free 7498K/8839K, paused 5ms+13ms
03-26 22:16:17.700: D/dalvikvm(628): GC_CONCURRENT freed 580K, 17% free 7370K/8839K, paused 5ms+4ms
03-26 22:16:17.960: D/dalvikvm(628): GC_CONCURRENT freed 448K, 17% free 7423K/8839K, paused 5ms+9ms
03-26 22:16:18.250: D/dalvikvm(628): GC_CONCURRENT freed 515K, 17% free 7361K/8839K, paused 5ms+4ms
03-26 22:16:18.540: D/dalvikvm(628): GC_CONCURRENT freed 440K, 17% free 7424K/8839K, paused 5ms+10ms
03-26 22:16:18.830: D/dalvikvm(628): GC_CONCURRENT freed 515K, 17% free 7363K/8839K, paused 4ms+4ms
03-26 22:16:19.090: D/dalvikvm(628): GC_CONCURRENT freed 439K, 17% free 7370K/8839K, paused 4ms+12ms
03-26 22:16:19.421: D/dalvikvm(628): GC_CONCURRENT freed 450K, 17% free 7422K/8839K, paused 5ms+9ms
03-26 22:16:19.730: D/dalvikvm(628): GC_CONCURRENT freed 509K, 17% free 7370K/8839K, paused 4ms+6ms
03-26 22:16:20.030: D/dalvikvm(628): GC_CONCURRENT freed 459K, 17% free 7421K/8839K, paused 4ms+4ms
03-26 22:16:20.370: D/dalvikvm(628): GC_CONCURRENT freed 514K, 17% free 7357K/8839K, paused 4ms+6ms
03-26 22:16:20.650: D/dalvikvm(628): GC_CONCURRENT freed 441K, 17% free 7425K/8839K, paused 4ms+14ms
03-26 22:16:20.950: D/dalvikvm(628): GC_CONCURRENT freed 518K, 17% free 7356K/8839K, paused 4ms+4ms
03-26 22:16:21.240: D/dalvikvm(628): GC_CONCURRENT freed 441K, 17% free 7423K/8839K, paused 4ms+4ms
03-26 22:16:21.490: D/dalvikvm(628): GC_CONCURRENT freed 516K, 17% free 7362K/8839K, paused 4ms+4ms
03-26 22:16:21.780: D/dalvikvm(628): GC_CONCURRENT freed 443K, 17% free 7422K/8839K, paused 4ms+9ms
03-26 22:16:22.090: D/dalvikvm(628): GC_CONCURRENT freed 515K, 17% free 7365K/8839K, paused 4ms+4ms
03-26 22:16:22.360: D/dalvikvm(628): GC_CONCURRENT freed 442K, 17% free 7423K/8839K, paused 4ms+4ms
03-26 22:16:22.660: D/dalvikvm(628): GC_CONCURRENT freed 515K, 17% free 7357K/8839K, paused 4ms+4ms
03-26 22:16:22.980: D/dalvikvm(628): GC_CONCURRENT freed 448K, 17% free 7420K/8839K, paused 4ms+4ms
03-26 22:16:23.260: D/dalvikvm(628): GC_CONCURRENT freed 508K, 17% free 7370K/8839K, paused 4ms+4ms
03-26 22:16:23.530: D/dalvikvm(628): GC_CONCURRENT freed 449K, 16% free 7435K/8839K, paused 4ms+4ms
03-26 22:16:24.419: D/dalvikvm(628): GC_CONCURRENT freed 511K, 18% free 7307K/8839K, paused 4ms+4ms
03-26 22:16:58.840: D/dalvikvm(628): GC_CONCURRENT freed 386K, 18% free 7305K/8839K, paused 4ms+4ms

das Letzte Log gehört zu den ominösen 30-sekunden intervallen des GC, was auch immer er da wegräumt...mir gefällt es jedenfalls nciht irgendwie


ich werde es mal morgen eine andere variante versuchen
und zu jedem Bitmap das ich skalieren muss ein objekt im speicher halten...damit tausche ich zwar performance gegen speicherverbrauch aber zur zeit verbraucht m,eine app eh nur ca 50 mb an ram im durchschnitt(bei den statistikender entwickleroptionen auf meinem handy nachgeguckt)

andere appps wie facebook oder spieleapps liegen schon über 150-220 mb von daher lets try this...


und nochwas: jetzt sind die meldung auf GC_CONCURRENT geswitcht was gut ist aber ob das vllt an meinem pc liegt (ich teste im emulator) weiß ich nciht

ich muss mal über USB laufen lassen mal gucken wie es mein note 4 verarbeitet(bessere CPU als mein pc hat es ja)

Der ursprüngliche Beitrag von 23:21 Uhr wurde um 23:47 Uhr ergänzt:

Hey ich nochmal habs jetzt doch ganz schnell gemacht heir der log nach ein bisschen rumspielen mit dem menü:

03-26 22:40:22.999: D/dalvikvm(531): GC_CONCURRENT freed 497K, 17% free 7426K/8903K, paused 4ms+8ms
03-26 22:40:23.599: D/dalvikvm(531): GC_CONCURRENT freed 499K, 17% free 7413K/8903K, paused 4ms+7ms
03-26 22:40:24.219: D/dalvikvm(531): GC_CONCURRENT freed 496K, 17% free 7395K/8903K, paused 4ms+5ms
03-26 22:40:24.839: D/dalvikvm(531): GC_CONCURRENT freed 465K, 17% free 7436K/8903K, paused 4ms+7ms
03-26 22:40:25.399: D/dalvikvm(531): GC_CONCURRENT freed 501K, 17% free 7437K/8903K, paused 5ms+4ms
03-26 22:40:25.999: D/dalvikvm(531): GC_CONCURRENT freed 492K, 17% free 7436K/8903K, paused 5ms+5ms
03-26 22:40:26.619: D/dalvikvm(531): GC_CONCURRENT freed 482K, 17% free 7422K/8903K, paused 5ms+5ms
03-26 22:40:27.199: D/dalvikvm(531): GC_CONCURRENT freed 477K, 17% free 7461K/8903K, paused 4ms+8ms
03-26 22:40:27.819: D/dalvikvm(531): GC_CONCURRENT freed 536K, 17% free 7423K/8903K, paused 5ms+7ms
03-26 22:40:28.679: D/dalvikvm(531): GC_CONCURRENT freed 428K, 18% free 7379K/8903K, paused 5ms+11ms

performance hat deutlich zu genommen!!!
ich hab zu testzwecken meinen thread so gebaut das er einfach durchrast und alles ancheinander aktualisiert und die view veranlasst die veränderungen zu speichern und auch ein fps anezige eingebaut

also jetzt komme ich selbst mit größter anstrengung nicht mehr unter 57 fps...das ist sehr gut davor fiel ich mit den 128x128 auf ca. 40 fps auch unter großen anstrengungen es weiter zu pushen und bei den 256x256 auch ohne anstrengung auf 16-17 fps...Anstrengung bedeutet ganz schnell hin udn ehrwischen damit die bitmaps sehr oft skaliert werden müssen

da bei Android die fps rate bei 60 gecappt ist unter darüber ncihts geht kann ich nicht sagen wieviel es über 60 fps werden könnte da ja der thread dementsprechend darauf warten dass die zeichenmethode wieder an den thread übergibt (das wäre mir schon wichtig um den drop der laufzeit beim skalieren zu beurteilen...er könnte ja von 125 fps oder nur von 70 auf 56-57 gedroppt sein amcht ja shcon ein utnerschied)





aber ok darum geht es in diesen thread ja nicht



whatever frage nach dem 30 sekunden intervallen steht immer ncoh im raum


ich glaube auch dass die 384k von den bitmaps kommen die regelmäßig weggeräumt werden
das habe ich daran gemerkt dass jetzt die size die weggeräumt wird sich vergrößert hat da ich ja jetzt 5 bitmaps mehr im speicher halte...

vllt defragmentiert der gc meinen heap schiebt die bitmaps woanders hin und löscht den alten speicherplatz

ich hoffe wirklich dass mir einer von euch der Ahnung damit hat weiterhelfen kann

 

[Thyrion]

Vielleicht hilft das ja schon weiter: GC_CONCURRENT « Jontas

EDIT: Ich mag mich irren, aber wie kannst du sicher sein, dass er freigebene Objekte aus deiner App aufräumt und nicht einfach Objekte, die vom OS oder anderen Apps im Hintergrund verwendet wurden?

 

[Jaiel]

Stimmt schon kann ich gar nicht
läuft im Emulator wie gesagt
Ich glaube dass es die Bitmaps sind aber sicher bin ich nicht leider

 

[sillage]

Man sieht es an der Grösse der VM.

Der ursprüngliche Beitrag von 10:31 Uhr wurde um 10:31 Uhr ergänzt:

Und der Prozess id

 

[Jaiel]

Ich überlege gerade ob es vllt an meinen for each schlafen liegen könnte mit dem ich meine arraylists durchgehen

Aber die sollten nicht getriggert werden falls nichts passiert

Ich muss nochmal genauer mein Code durchgehen

 

[Jaiel]

kleines Update es scheint wohl nur etwas mit dem Emulator zu sein weswegen ich eine GC bekam


per USB debugging läuft alles wie es soll ohne GC


Danke an alle


PS:

was sollen diese Meldungen eig.?

03-30 03:01:48.710: D/ViewRootImpl(13244): ViewPostImeInputStage ACTION_DOWN
03-30 03:01:49.240: D/ViewRootImpl(13244): ViewPostImeInputStage ACTION_DOWN
03-30 03:01:50.400: D/ViewRootImpl(13244): ViewPostImeInputStage ACTION_DOWN
03-30 03:01:51.390: D/ViewRootImpl(13244): ViewPostImeInputStage ACTION_DOWN

warum ist ein onDown so wichtig?