dalvikvm: GC_FOR-ALLOC

[benitovc]

When y run philadelphia on an android device, I receive a lot of messages like: D/dalvikvm: GC_FOR_ALLOC freed 1025K, 47% free 8909K/16584K, paused 21ms, total 22ms D/dalvikvm: GC_FOR_ALLOC freed 2232K, 47% free 8905K/16584K, paused 23ms, total 23ms

[jvirtanen]

Hi @benitovc! Obviously it's very hard to say what in your application causes memory allocation, but regarding Philadelphia, check that you are not using any of the following on the hot path:

• FIXMessage.fromString()
• FIXMessage#toString()
• FIXSession#create()
• FIXValue#asString()

[benitovc]

When a new message arrives to my client, I´m printing using FIXMessage.toString and FIXValue.asString in order to process message, but this D/dalvikvm: GC_FOR_ALLOC appears more when there is no message flow. After connection is done, in Logcat I receive something like: 08-15 06:55:04.563 10624-10772/com.bvcapps.marketdata A/texto: Abriendo conexión FIX con /192.168.0.4:5125 Ambiente:CL sender:CFIX10 target:DFIXS01 usuario:BCISSCLA CFIX_MD 08-15 06:55:05.143 10624-10772/com.bvcapps.marketdata A/texto: Conexión FIX establecida com.bvcapps.marketdata.ConexionFIX@420ac108 08-15 06:55:05.323 10624-10772/com.bvcapps.marketdata A/texto: ---------- FIXSession Logon Usuario autorizado 08-15 06:55:05.333 10624-10772/com.bvcapps.marketdata A/texto: IN:35=BU|34=2|49=DFIXS01|52=20180815-11:55:07.969|56=CFIX10|15=CLP|423=20|562=250000|576=1|577=0|1205=1|1206=0|1208=0.01|1232=1|1308=G|1237=1|40=2|1239=3|59=1|59=3|59=4|1245=USD|1300=39|1301=XBCL|1306=1|1393=1|1394=H4NQVI|1396=D￳lar Spot Extrabancario|1656=1|1535=1|1536=USD/CLP|1786=0| 08-15 06:55:05.363 10624-10772/com.bvcapps.marketdata A/texto: IN:35=W|34=3|49=DFIXS01|52=20180815-11:55:08.003|56=CFIX10|55=USD/CLP|262=2|268=1|269=J|911=1|1021=3|1300=39|1301=XBCL| 08-15 06:55:05.553 10624-10772/com.bvcapps.marketdata D/dalvikvm: GC_FOR_ALLOC freed 5993K, 47% free 8879K/16584K, paused 44ms, total 45ms 08-15 06:55:05.683 10624-10772/com.bvcapps.marketdata D/dalvikvm: GC_FOR_ALLOC freed 1057K, 47% free 8845K/16584K, paused 20ms, total 20ms 08-15 06:55:05.803 10624-10772/com.bvcapps.marketdata D/dalvikvm: GC_FOR_ALLOC freed 1024K, 47% free 8845K/16584K, paused 20ms, total 20ms 08-15 06:55:05.993 10624-10772/com.bvcapps.marketdata D/dalvikvm: GC_FOR_ALLOC freed 2163K, 47% free 8845K/16584K, paused 22ms, total 22ms 08-15 06:55:06.113 10624-10772/com.bvcapps.marketdata D/dalvikvm: GC_FOR_ALLOC freed 1024K, 47% free 8845K/16584K, paused 19ms, total 19ms

And this D/dalvikvm is continuously appearing until the connection or the application are finished.

[jvirtanen]

Are you using a Selector? On JDK, that allocates memory. Apart from that, I don't really know how the Dalvik runtime differs from the JRE in regard to the SocketChannel implementation. Have you ensured that messaging over a raw SocketChannel causes no memory allocations on Dalvik?

[benitovc]

Well, for the creation of channel I´m using: channel = SocketChannel.open(); I´m not using Selector. But in Android documentation the class SocketChannel has a protected constructor: SocketChannel(SelectorProvider provider) I don´t know if it is called. I think the messaging over is coused by socket channel or someting in philadelphia because when connection is not established, the messages does not appear.

[jvirtanen]

Can you run a profiler (or even just jmap -histo periodically) to see what types of objects are getting allocated?

[benitovc]

Hi Jussi, it´s my first time I run a profile, I just capture when no fix message were traveling, only my FIX Client was connected. If you can´t see the image, tell me to send it via mail. Thanks.

[jvirtanen]

It looks like something is allocating memory in SocketChannel#read(). Can you see what types of objects get allocated?

[jheusser]

@benitovc I think it's likely the profiler causing the garbage on socket read. Have you tried disabling socket read/write profiling?

[jvirtanen]

Closing this due to lack of further updates.