A separate thread freezes while sending HTTP seque

2019-09-15 03:22发布

站内文章 / Android
47 0 0

问题:

I'm trying to build a remote control Android app and keep failing to use the network properly. The commands are sent in a separate thread with a delay of approximately 100 ms (plus sending) using HTTP (okhttp3).

The problem is the app sometimes freezes the transmittion printing something like this to logcat:

03-29 02:18:31.249 25191-25191/com.example.control D/CommandSender: http://192.168.1.185/drive?m1s=988&m2s=927&dir=ff s: 6557 f: 0
03-29 02:18:31.259 25191-25191/com.example.control D/CommandSender: http://192.168.1.185/drive?m1s=988&m2s=952&dir=ff s: 6557 f: 0
03-29 02:18:31.489 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 02:18:32.060 505-600/? D/Tethering: TetherModeAliveState.processMessage what=4
03-29 02:18:32.060 505-600/? D/Tethering: renewing mobile connection - requeuing for another 40000ms
03-29 02:18:32.060 505-600/? D/ConnectivityService: startUsingNetworkFeature for net 0: enableDUN by 505/1000
03-29 02:18:32.060 505-600/? D/ConnectivityService: Disconnect 4 in 60000ms
03-29 02:18:32.060 505-600/? D/ConnectivityService: reconnecting to special network 4
03-29 02:18:32.060 505-598/? D/ConnectivityService: issue reconnect to special network:4
03-29 02:18:32.060 505-598/? D/MobileDataStateTracker: dun: setTeardownRequested(false)
03-29 02:18:32.430 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 02:18:32.931 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 02:18:33.442 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 02:18:34.352 25191-25191/com.example.control D/CommandSender: http://192.168.1.185/drive?m1s=988&m2s=964&dir=ff s: 6558 f: 0

where s: value is the number of successes and f: value is the number of failures. Notice the 3s delay between the CommandSender log lines. Another typical type of messages during the freezes is about GC.

Both devices I tested on show similar behaviour (HTC One S and Alcatel Idol 3, have pretty much nothing in common both in hardware and software).

At the same time sending the requests using a JavaScript page from the browsers on the same devices shows no freezes or other communication problems while the request period may be as little as 25 ms avg.

The code to send the requests:

/*
 * In activity
 */
private CommandSender sender;
private Thread connectionThread;

@Override
protected void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);

    setContentView(R.layout.control);

    // setting up other elements

    sender = new CommandSender (ipString, this) {
        @Override
        protected void onSuccess () {}

        @Override
        protected void onFailure () {
            Toast.makeText (ControlActivity.this, R.string.cmd_send_failure, Toast.LENGTH_SHORT)
                 .show ();
        }
    };
}

@Override
protected void onResume () {
    super.onResume ();
    connectionThread = new Thread(new Runnable() {
        public void run() {
            while (true) {
                try {
                    sender.send (s1value, s2value); // slider values
                    Thread.sleep(100);
                } catch (InterruptedException e) {
                    return;
                }
            }
        }
    });
    connectionThread.start ();
}

/*
 * In CommandSender.java
 */
abstract class CommandSender
{
    private final String address; // ip string
    private final OkHttpClient client = new OkHttpClient();
    private final WeakReference<Activity> activity;

    private int successCounter = 0;
    private int failureCounter = 0;

    public CommandSender (String address, Activity activity) {
        this.address = address;
        this.activity = new WeakReference<> (activity);
    }

    public void send (int m1speed, int m2speed) {
        String url = formUrl (address, m1speed, m2speed);
        Request request = new Request.Builder ().url (url).build ();
        client.newCall(request).enqueue(new Callback () {
            @Override
            public void onFailure (Call c, IOException e) {
                activity.get ().runOnUiThread (new Runnable () {
                    @Override
                    public void run () {
                        CommandSender.this.onFailure ();
                    }
                });
                failureCounter++;
            }

            @Override
            public void onResponse (Call c, Response response) throws IOException {
                successCounter++;
                if (!response.isSuccessful ())
                    throw new IOException ("Unexpected code " + response);
                activity.get ().runOnUiThread (new Runnable () {
                    @Override
                    public void run () {
                        Log.d ("CommandSender", url + " s: " + successCounter + " f: " + failureCounter);
                        CommandSender.this.onSuccess ();
                    }
                });
            }
        });
    }

    private static String formUrl (String address, int m1speed, int m2speed)
    {
        // do it
    }

    abstract protected void onSuccess ();
    abstract protected void onFailure ();
}

Considering the browser has no problems with connection, I am doing something wrong here. So what's wrong?

UPD1:

It definitely has something to do with system tasks. Anyway, it's strange that okhttp3 gets interrupted while, for instance, the browser does not.
Another log for this case (12 s freeze!):

03-29 08:34:17.898 21167-21167/com.example.control D/CommandSender: http://192.168.1.185/drive?m1s=801&m2s=805&dir=ff s: 204 f: 3
03-29 08:34:18.108 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:18.379 21167-21167/com.example.control D/CommandSender: http://192.168.1.185/drive?m1s=732&m2s=919&dir=ff s: 205 f: 3
03-29 08:34:18.619 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:18.919 21167-21167/com.example.control D/CommandSender: http://192.168.1.185/drive?m1s=769&m2s=927&dir=ff s: 206 f: 3
03-29 08:34:19.210 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:19.740 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:20.291 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:20.451 505-919/? D/Process: killProcessQuiet, pid=9971
03-29 08:34:20.451 505-919/? I/ActivityManager: No longer want com.maxmpz.audioplayer (pid 9971): hidden #16, adj=15
03-29 08:34:20.461 505-919/? D/Process: dalvik.system.VMStack.getThreadStackTrace(Native Method)
03-29 08:34:20.461 505-919/? D/Process: java.lang.Thread.getStackTrace(Thread.java:599)
03-29 08:34:20.461 505-919/? D/Process: android.os.Process.killProcessQuiet(Process.java:837)
03-29 08:34:20.461 505-919/? D/Process: com.android.server.am.ActivityManagerService.updateOomAdjLocked(ActivityManagerService.java:15735)
03-29 08:34:20.461 505-919/? D/Process: com.android.server.am.ActivityManagerService.setProcessForeground(ActivityManagerService.java:5041)
03-29 08:34:20.461 505-919/? D/Process: com.android.server.NotificationManagerService.keepProcessAliveLocked(NotificationManagerService.java:750)
03-29 08:34:20.461 505-919/? D/Process: com.android.server.NotificationManagerService.enqueueToast(NotificationManagerService.java:619)
03-29 08:34:20.461 505-919/? D/Process: android.app.INotificationManager$Stub.onTransact(INotificationManager.java:104)
03-29 08:34:20.461 505-919/? D/Process: android.os.Binder.execTransact(Binder.java:338)
03-29 08:34:20.461 505-919/? D/Process: dalvik.system.NativeStart.run(Native Method)
03-29 08:34:20.491 209-7892/? D/memalloc: ion: Allocated buffer base:0x41cb5000 size:147456 fd:38
03-29 08:34:20.491 21167-21167/com.example.control D/memalloc: ion: Mapped buffer base:0x52fe5000 size:147456 offset:0 fd:99
03-29 08:34:20.511 209-277/? I/Adreno200-EGLSUB: <CreateImage:897>: Android Image
03-29 08:34:20.511 209-277/? I/Adreno200-EGLSUB: <GetImageAttributes:1106>: RGBA_8888
03-29 08:34:20.521 890-890/? D/dalvikvm: GC_FOR_ALLOC freed 1160K, 36% free 5526K/8611K, paused 41ms
03-29 08:34:20.541 505-763/? W/ContentService: binderDied() at ObserverNode
03-29 08:34:20.541 505-763/? W/ActivityManager: Scheduling restart of crashed service com.maxmpz.audioplayer/.player.HeadsetMicroService in 5000ms
03-29 08:34:20.571 902-902/? I/PreJBNotificationService: onAccessibilityEvent
03-29 08:34:20.911 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:21.432 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:22.103 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:22.463 21167-21167/com.example.control D/memalloc: ion: Unmapping buffer  base:0x52fe5000 size:147456
03-29 08:34:22.503 209-7961/? D/memalloc: ion: Allocated buffer base:0x41e02000 size:147456 fd:66
03-29 08:34:22.503 21167-21167/com.example.control D/memalloc: ion: Mapped buffer base:0x52fe5000 size:147456 offset:0 fd:99
03-29 08:34:22.513 209-277/? D/memalloc: ion: Freeing buffer base:0x41cb5000 size:147456 fd:38
03-29 08:34:22.513 209-277/? D/memalloc: ion: Unmapping buffer  base:0x41cb5000 size:147456
03-29 08:34:22.513 209-277/? I/Adreno200-EGLSUB: <CreateImage:897>: Android Image
03-29 08:34:22.513 209-277/? I/Adreno200-EGLSUB: <GetImageAttributes:1106>: RGBA_8888
03-29 08:34:22.533 890-890/? D/dalvikvm: GC_FOR_ALLOC freed 1158K, 36% free 5526K/8611K, paused 51ms
03-29 08:34:22.563 902-902/? I/PreJBNotificationService: onAccessibilityEvent
03-29 08:34:22.603 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:23.004 505-543/? D/BatteryService: updateBatteryStats ======================================
03-29 08:34:23.134 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:23.154 505-557/? D/BatteryService: UEvent updateBatteryStats
03-29 08:34:23.164 505-543/? D/HtcPowerSaver: Recived battery changed intent.
03-29 08:34:23.164 505-543/? D/UsbnetService: BroadcastReceiver::onReceive+
03-29 08:34:23.164 505-543/? D/UsbnetService: onReceive BATTERY_CHANGED
03-29 08:34:23.164 505-543/? D/UsbnetService:  --> pluggedType = 2, mPluggedType = 0, mScreenOff = false
03-29 08:34:23.164 505-543/? D/UsbnetService: BroadcastReceiver::onReceive-
03-29 08:34:23.164 505-543/? D/HtcPowerSaver: Checking...
03-29 08:34:23.164 505-543/? I/HtcPowerSaver: >> updateStatus
03-29 08:34:23.164 505-543/? I/HtcPowerSaver: currentStatus=8000, currentLevel=93, enableLevel=20, enable=false, popDialog=false, statusChangeTo=-1
03-29 08:34:23.164 505-543/? I/HtcPowerSaver: << updateStatus
03-29 08:34:23.164 505-557/? D/PackageManager: Failed to get PackageInfo!, pkg:com.htc.demoflorebooter, flags:1
03-29 08:34:23.164 647-647/? D/StatusBar.BatteryController: updateBattery level=93 icon=17302788 status=2
03-29 08:34:23.164 647-647/? D/PowerUI: closing low battery warning: level=93
03-29 08:34:23.164 647-647/? D/PowerUI: plugged = true, health = 2, mBatteryLevel = 93, mPluggedBatteryLevel = 91, mLowBatteryWarningLevel2 = 25, mshowLowChargingWarning2 = true
03-29 08:34:23.164 505-543/? D/NotificationService: mIntentReceiver() Intent.ACTION_BATTERY_CHANGED
03-29 08:34:23.164 505-543/? D/PowerManagerService: runHtcPowerSaverCheck ======================================
03-29 08:34:23.634 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:24.285 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:24.465 21167-21167/com.example.control D/memalloc: ion: Unmapping buffer  base:0x52fe5000 size:147456
03-29 08:34:24.505 209-277/? D/memalloc: ion: Freeing buffer base:0x41e02000 size:147456 fd:66
03-29 08:34:24.505 209-277/? D/memalloc: ion: Unmapping buffer  base:0x41e02000 size:147456
03-29 08:34:24.785 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:25.296 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:25.566 505-544/? I/ActivityManager: Start proc com.maxmpz.audioplayer for service com.maxmpz.audioplayer/.player.HeadsetMicroService: pid=23572 uid=10203 gids={1015, 3003, 3002}
03-29 08:34:25.807 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:25.807 23572-23572/? I/dalvikvm: Could not find method com.maxmpz.audioplayer.Application.getExternalFilesDirs, referenced from method com.maxmpz.audioplayer.Application.ll11
03-29 08:34:25.807 23572-23572/? W/dalvikvm: VFY: unable to resolve virtual method 5688: Lcom/maxmpz/audioplayer/Application;.getExternalFilesDirs (Ljava/lang/String;)[Ljava/io/File;
03-29 08:34:25.807 23572-23572/? D/dalvikvm: VFY: replacing opcode 0x6e at 0x002e
03-29 08:34:25.827 23572-23572/? W/audioplayer.Application: Detected NEON support
03-29 08:34:25.827 23572-23572/? W/audioplayer.Application: Detected HTC
03-29 08:34:25.827 23572-23572/? I/dalvikvm: Could not find method android.widget.RemoteViews.setTextViewTextSize, referenced from method com.maxmpz.audioplayer.widgetpackcommon.CommonWidgetProvider.ll1l
03-29 08:34:25.827 23572-23572/? W/dalvikvm: VFY: unable to resolve virtual method 4565: Landroid/widget/RemoteViews;.setTextViewTextSize (IIF)V
03-29 08:34:25.827 23572-23572/? D/dalvikvm: VFY: replacing opcode 0x6e at 0x0007
03-29 08:34:25.827 23572-23572/? W/audioplayer.Application: htcSenseVersion=400
03-29 08:34:25.837 23572-23572/? I/audioplayer.Application: man=HTC pro=ville mod=HTC One S dev=ville type=user board=MSM8960 rel=4.0.4 osVersion=3.0.8-01575-gdcba118
03-29 08:34:25.837 23572-23572/? W/audioplayer.Application: Poweramp edition: arm-play
03-29 08:34:25.837 23572-23572/? I/ActivityThread: Pub com.maxmpz.audioplayer.data: com.maxmpz.audioplayer.rest.RestProvider
03-29 08:34:25.837 23572-23572/? W/audioplayer.Application: tab=false screenSize=2 dpi=240 den=1.5 swdp=360 w/h=540x960
03-29 08:34:25.887 212-212/? D/AudioFlinger: no match values for active_ap
03-29 08:34:25.887 212-212/? E/AudioHardwareALSA: unsupported AP: Music
03-29 08:34:25.887 212-455/? D/AudioFlinger: no match values for active_ap
03-29 08:34:25.887 212-455/? E/AudioHardwareALSA: unsupported AP: Music
03-29 08:34:25.887 212-30925/? D/AudioFlinger: no match values for active_ap
03-29 08:34:25.887 212-30925/? E/AudioHardwareALSA: unsupported AP: Music
03-29 08:34:26.287 647-647/? D/PhoneStatusBarPolicy: isCdma=false hasService=true mSimState=UNKNOWN gprsState=1 mDataState=0 dataActivity=3 htcModemLinkOn=false hspa=true
03-29 08:34:26.327 505-569/? I/PowerManagerService-JNI: [Stability] PowerManagerService_userActivity JNI pass power key event to PowerManagerService userActivity()
03-29 08:34:27.198 16321-16321/? I/hostapd: wlan0: AP-STA-CONNECTED 68:5d:43:da:ef:62
03-29 08:34:27.198 16321-16321/? I/hostapd: station join 68:5D:43:DA:EF:62
03-29 08:34:27.198 505-16290/? I/hostapd: handle event, recv=(<3>AP-STA-CONNECTED 68:5d:43:da:ef:62,37), result=0
03-29 08:34:27.198 505-16290/? I/hostapd: handle event: result=0 nread=37 string="<3>AP-STA-CONNECTED 68:5d:43:da:ef:62"
03-29 08:34:27.208 505-16290/? D/SoftapMonitor: received event=3, STA_JOIN
03-29 08:34:27.208 505-16290/? I/hostapd: Handle event.........
03-29 08:34:27.208 206-264/? D/QCSDK-: CMD INPUT
03-29 08:34:27.208 505-591/? D/Tethering: [isWifi] getHotspotEnabled: true
03-29 08:34:27.208 505-591/? D/WifiStateMachine: WiFiDisplay: getWifidisplayApEnabled=false
03-29 08:34:27.208 505-591/? D/WifiStateMachine: WiFiDisplay: getWifidisplayApEnabled=false
03-29 08:34:27.208 505-591/? D/Tethering: [isWifi] getWifidisplayApEnabled: false
03-29 08:34:27.208 505-591/? D/Tethering: [isWifi] iface: wlan0 && wifi.softap.interface: wlan0
03-29 08:34:27.208 505-591/? D/Tethering: interfaceStatusChanged wlan0, true
03-29 08:34:27.218 206-264/? D/QCSDK-: CMD OUTPUT [success sta_mac_list=5C:CF:7F:D5:07:EA 68:5D:43:DA:EF:62] len :56
03-29 08:34:27.218 505-596/? D/WifiStateMachine: cancel SoftAP sleep policy: mUser=2, syncGetWifiApState=13
03-29 08:34:27.218 505-596/? E/NetworkManagementService: DEBUG softap getassoclist: 2|5C:CF:7F:D5:07:EA,68:5D:43:DA:EF:62,
03-29 08:34:27.218 505-596/? D/WifiStateMachine: SoftAP update assoc list: mUser=2
03-29 08:34:27.228 505-600/? D/Tethering: >>>>>>receive ASSOC_LIST_CHANGE_ACTION<<<<<<
03-29 08:34:27.228 505-600/? D/WifiStateMachine: WiFiDisplay: getWifidisplayApEnabled=false
03-29 08:34:27.228 505-600/? D/WifiStateMachine: WiFiDisplay: getWifidisplayApEnabled=false
03-29 08:34:27.228 505-600/? D/Tethering: showTetheredNotification: 17303460
03-29 08:34:27.228 206-264/? D/QCSDK-: CMD INPUT
03-29 08:34:27.228 206-264/? D/QCSDK-: CMD OUTPUT [success sta_mac_list=5C:CF:7F:D5:07:EA 68:5D:43:DA:EF:62] len :56
03-29 08:34:27.228 505-600/? E/NetworkManagementService: DEBUG softap getassoclist: 2|5C:CF:7F:D5:07:EA,68:5D:43:DA:EF:62,
03-29 08:34:27.238 505-600/? D/Tethering: icon change: 17303460 -> 17303460
03-29 08:34:27.288 16330-16330/? I/dnsmasq: DHCPREQUEST(wlan0) 192.168.1.157 68:5d:43:da:ef:62 
03-29 08:34:27.288 16330-16330/? I/dnsmasq: DHCPACK(wlan0) 192.168.1.157 68:5d:43:da:ef:62 AsusU32VJ
03-29 08:34:27.368 902-902/? I/PreJBNotificationService: onAccessibilityEvent
03-29 08:34:27.368 902-902/? I/PreJBNotificationService: ticker: подключенных пользователей: 2
03-29 08:34:27.368 902-902/? I/PreJBNotificationService: icon: 17303460
03-29 08:34:27.368 902-902/? I/PreJBNotificationService: package: android
03-29 08:34:27.368 902-902/? I/PreJBNotificationService: Ongoing notification, returning
03-29 08:34:30.572 21167-21167/com.example.control D/CommandSender: http://192.168.1.185/drive?m1s=602&m2s=988&dir=ff s: 207 f: 5
标签： android multithreading http freeze okhttp3
举报

收藏的人(0)

Ta的文章 更多文章
登录 后发表评论
0条评论
还没有人评论过~