B4J Question FCM Running Slow

[aaronk]

Hi,

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

Sending Firebase Message - Object should first be initialized / timeout

Hi, I am running the following code to send a firebase push notification: Private Sub SendMessage(Topic As String, Title As String, Body As String, sound As String) As ResumableSub Dim Token As String = GetTokenValue(ServiceAccountFilePath) Dim Job As HttpJob Job.Initialize(""...

www.b4x.com

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.

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 ?

 

[Erel]

The timeout will only stop the request if no data is transferred.
Are you calling SendMessage or RunMe concurrently? You should.

 

[aaronk]

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 ?

 

[Erel]

Maybe I missed something.

You are sending a single message and measuring the time it takes for the message to arrive on the device?

 

[aaronk]

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.

 

[Erel]

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:

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

And add this build symbol: HU2_PUBLIC

 

[aaronk]

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 ?

 

[DonManfred]

does it mean I have 100 connections rather than 5 ?

i guess yes

 

[aaronk]

So far it's working OK, but will monitor it over the next 24-48 hours and see how it goes.

 

[aaronk]

So far this has fixed the issue. It hasn't slowed down since, so I guess that was the issue.