B4J Question FCM Running Slow

aaronk

Well-Known Member
Licensed User
Longtime User
Hi,

In the past I have mentioned I had an issue with Firebase push notifications having a timeout issue per the following:


This is a follow up to that, as I am noticing something that may or may not be related.

On average by B4J app will send around 150 Firebase push notifications per minute.

I am using the code as per below.

The Topic, body, title and sound changes for each push notification. It only takes 0-1ms to generate these values, which is fine.

B4X:
Sub RunMe

Dim Topic as string = "test"
Dim Body as string = "Body test here"
Dim Title as string = "Title here"
dim sound as string = "default"

Dim n As Long = DateTime.now
Wait For (SendMessage(Topic, Title, Body, sound)) Complete (Success1 As Boolean)
Log("Total Time Took: " & (DateTime.Now - n))

End Sub

Public Sub SendMessage(Topic As String, Title As String, Body As String, sound As String) As ResumableSub
Try

    Dim Token As String = GetTokenValue(ServiceAccountFilePath)
    
    Dim Job As HttpJob
    Job.Initialize("", Me)
    Dim data As Map = CreateMap("title": Title, "body": Body)
    Dim message As Map = CreateMap("topic": Topic, "data": data)
    If Topic.StartsWith("ios_") Then
        'B4i
        Dim Badge As Int = 0
        Dim iosalert As Map =  CreateMap("title": Title, "body": Body)
        message.Put("notification", iosalert)
        message.Put("apns", CreateMap("headers": _
            CreateMap("apns-priority": "10"), _
            "payload": CreateMap("aps": CreateMap("sound": sound, "badge": Badge))))
    Else
        'B4A
        message.Put("android", CreateMap("priority": "high"))
    End If
    Dim jg As JSONGenerator
    jg.Initialize(CreateMap("message": message))
    
'    Log("Sending")
'    Log(jg.ToPrettyString(4))
    
    Job.PostString($"https://fcm.googleapis.com/v1/projects/${ProjectID}/messages:send"$, jg.ToString)
    Job.GetRequest.SetContentType("application/json;charset=UTF-8")
    Job.GetRequest.SetHeader("Authorization", "Bearer " & Token)
    Job.GetRequest.Timeout = 5000

        Wait For (Job) JobDone(Job As HttpJob)
        If Job.Success Then
            'Log(Job.GetString)
            Job.Release
        Else
            Log(Job.ErrorMessage)
            Log("Failed to process Firebase. Topic = " & Topic)
            Job.Release
        End If
        
        Job.Release
    
    Return True
Catch
    Job.Release
    Log(LastException.Message)
     Return False
End Try
End Sub

Private Sub GetTokenValue (FilePath As String) As String
    Dim GoogleCredentials As JavaObject
    GoogleCredentials.InitializeStatic("com.google.auth.oauth2.GoogleCredentials")
    Dim Credentials As JavaObject = GoogleCredentials.RunMethodJO("fromStream", Array(File.OpenInput(FilePath, ""))) _
        .RunMethod("createScoped", Array(Array As String("https://www.googleapis.com/auth/firebase.messaging")))
    Credentials.RunMethod("refreshIfExpired", Null)
    Return Credentials.RunMethodJO("getAccessToken", Null).RunMethod("getTokenValue", Null)
End Sub

What I am finding is it's taking some time to process the SendMessage function. At the start the push notifications are fairly instant, and then all of a sudden it takes 10 seconds and then takes 1-2 minutes then around 20 minutes before I get the push notification on my phone.

For troubleshooting, I am logging how long it takes to run the 'Wait For' part of the code as per my code above.

Yesterday running the exact same code, it was logging around 300-400.

Today when I run the exact same code (made not programming changes) it seems to log 400, 570, 1246, 837, 833, 7745, 6620, 7261, 11715, 12307, 1692, 1198, 29010, 28248, 41720...

After around 5 minutes its logging around 160637, 164870, 173864..

I then moved the code I used to log how long it took to run the code, to the Sub SendMessage rather than logging after the 'Wait for', but it was logging roughly the same time. (so I assume it doesn't matter if I log it after the Wait For or in the sub since it returned the same value.

I am running the above on a AWS EC2 t3.medium using Ubuntu 22.04

As it started to run slow, I tried to run the code on another VPS with a different hosting company but have the same result.

I then ran the same code in the B4J IDE in release mode on my development machine, Windows 10 in a VM on my MacBook Pro and it seems to run fine. It logs 900-1200 in the IDE when it processes the messages. Which I would call acceptable as the push notification arrived within 1-2 seconds after the RunMe sub was called.

During all my tests it never logs any timeouts or errors, which is strange since it took longer to process but the timeout is set to 5000. So there must be something else causing it to run slow somewhere before it calls Job.PostString(..) as it was logging values more than the timeout value (5000).

I then logged to see how long the GetTokenValue took to get the value and it takes 30-40ms each time.

I am using B4J 10.00
Java jdk-14.0.1

I checked the internet speed on the AWS EC2 and it was as per below which I don't think is going to be the issue since my internet on my computer is a lot slower and it was working.
Download: 1911.46 Mbit/s
Upload: 1694.04 Mbit/s

Any ideas on where else to look to see why it's taking so long to run the code ?
 

aaronk

Well-Known Member
Licensed User
Longtime User
Are you calling SendMessage or RunMe concurrently? You should.
In the B4J app I am only calling RunMe when I send the push notification. This sub then calls SendMessage with 'Wait For' like in my code in post 1.

Are you meaning I should do it another way ?
 
Upvote 0

aaronk

Well-Known Member
Licensed User
Longtime User
Short answer, no I am measuring the time it takes to send the outgoing message from the B4J app.

I will help explain it in 2 other ways which might help understand it in more detail.

1. In my B4J app I have a sub that receives MQTT messages. If the MQTT message equals a value I am sending a FCM. It sends around 150 messages per minute as that is how many equals the value.

To help understand how I am sending the FCM I created the RunMe sub for testing. So imagine the RunMe sub running 150 times per minute and the topic is different each and every time.

I am logging how long it takes to send out the message from the B4J server. At the start the SendMessage sub sends fairly quickly 300-400ms but then starts to lag and takes longer to send the message in the SendMessage sub. So after it sends the message from the B4J server I am not worried about how long before the user gets the notification as that part it out of my hands. I only care how long it takes B4J to send the message.

2. To help explain it in another way, imagine a bus door opening and the user subscribes to the FCM topic for every time the bus door opens or closes.

The bus door opens and a MQTT message is sent to my B4J app. I then have a MAP in my B4J app and if the MAP contains the FCM topic (as I only want to send FCM to users who have subscripted and not just send it each and every time), I am then sending the FCM message like shown in the RunMe sub. Checking the MAP before sending the message only takes 0-1ms.

At the start the B4J app runs the SendMessage sub within 300-400ms, which I think is good. This is how long it took to send the message to Firebase. If I leave the B4J app running and it starts to lag and the SendMessage sub takes longer and longer to run.

The door opens on the bus, and we get the notification within 1-2 seconds which is fairly instant. But then all of a sudden (in 1-2 minutes after running the B4J app), the push notification is received 10-20 seconds later after the door opens.

Then if we wait a few more minutes, the door opens again, and the push notification then arrives 5-10 minutes later. (In the body of the notification I am including the timestamp so I know the time the B4J app processed the title/body of the message and that timestamp is correct when I get the message on my Android/iOS device).

If I then log how long it's taking to run the sub SendMessage in the B4J app, it's taking longer to run that sub in the B4J app. So the B4J is slowing down in sending the outgoing message which I can't work out why it's slowing down.

It's like the SendMessage sub can only run once at a time, and it needs to wait for that to finish sending the message before it allows it to send the next one. I know it most likely isn't the case, but that is what it looks like.

Hope that makes sense.
 
Upvote 0

Erel

B4X founder
Staff member
Licensed User
Longtime User
You are not waiting for RunMe to complete before sending another message, right?

OkHttp limits by default the number of connections made to a host to 5. This means that the 6th call will wait for a previous one to complete.

Try to configure this limit with this code at the beginning of your app:
B4X:
HttpUtils2Service.Service_Create
HttpUtils2Service.hc.As(JavaObject).GetFieldJO("client").RunMethodJO("dispatcher", Null).RunMethod("setMaxRequestsPerHost", Array(100))

And add this build symbol: HU2_PUBLIC
 
Upvote 0

aaronk

Well-Known Member
Licensed User
Longtime User
You are not waiting for RunMe to complete before sending another message, right?
That is correct, I am running that without waiting for the previous one to finish.

By adding this code, does it mean I have 100 connections rather than 5 ?
 
Upvote 0

DonManfred

Expert
Licensed User
Longtime User
Upvote 0

aaronk

Well-Known Member
Licensed User
Longtime User
So far it's working OK, but will monitor it over the next 24-48 hours and see how it goes.
 
Upvote 0

aaronk

Well-Known Member
Licensed User
Longtime User
I spoke to soon. It seems to be running slow again.

I added:
B4X:
HttpUtils2Service.Service_Create
HttpUtils2Service.hc.As(JavaObject).GetFieldJO("client").RunMethodJO("dispatcher", Null).RunMethod("setMaxRequestsPerHost", Array(100))

This seem to fix the issue for a few months and now it's running slow again. I tried changing the Array(100) to (300) to see if that helps, but it didn't.

For troubleshooting I am logging the MQTT incoming data and it logs in realtime.
Once the MQTT message is received I then pass the event to a function that creates Title/Body of the message to send. This is done in < 30ms. So I know this part can't be causing the issue.

I then pass the message it creates to the function that sends the Firebase message. It takes around 600-700ms for the message to be sent.

I think it's queuing the outgoing message and only allowing some messages to be sent at one time and then causing it to be delayed to be sent.

Any other way in fixing this delay ?
 
Upvote 0

aaronk

Well-Known Member
Licensed User
Longtime User
Why do you need to send so many messages? Is each message different? Maybe you can group them.
Each message is sent to different topics, and I can't group them since it's for different users.

As an example think of it as a bus door, each time the bus door opens it sends a unique topic and message advising the door has opened.

Depending who subscribes to the topic will get the message so not all users are getting the message. There most likely be 1-2 devices subscribe to the same topic.

In the middle of the night things seem to work fine after a stop then start the B4J app. Then throughout the day the push notifications run slow again.

There is a few thing I can think of:

1. The B4J app can't keep up with sending the FCM Messages and it's queuing the messages.
2. FCM is taking longer to accept the API call. At the moment it takes 600-700ms to accept the API. When there is a delay it is around 23000ms if not longer to process each message.

I can't work out if B4J can't keep up and is limiting the number of outgoing messages in the B4J app, or if Firebase is throttling the API calls and causing the issue.

Every time the B4J app sends a FCM message I am adding a one to a counter and then every minute logging the counter value to work out how many messages it's sending per minute.

I am actually running 2 B4J apps that are triggering FCM messages. The other app is working fine. It is only processing 2-3 messages per minute, but the B4J app that I am having the issue with is sending around 150-200 messages per minute.
 
Upvote 0
Top