SENTINELITE / StreamDeck-Shortcuts

Run Shortcuts straight from your Elgato StreamDeck!
https://sentinelite.com/discord-shortcuts-support
GNU Affero General Public License v3.0
116 stars 7 forks source link

StreamDeck-Shortcuts consumes 100% CPU time #19

Open jokalode opened 1 year ago

jokalode commented 1 year ago

When entering the office first time in the morning, I have observed that the computer was very active, cooling fans spinning more than usual, while it should actually be sleeping. Checking CPU time it was StreamDeck-Shortcuts consuming 100 % CPU time. Killing the process, the computer went back to normal.

I can't remember having observed that behaviour while working on the computer. But I routinely build software on the computer. So it may just have escaped my notice.

Will observe if it is related to the sleep state, or not.

This relates to version 1.0.7.1.

wesbland commented 1 year ago

Same for me, though I don't see any logs that look relevant.

SENTINELITE commented 1 year ago

Hey, @wesbland!

Did you see this after the computer woke up from a rest state?

@jokalode, I've gotten this a few times over the past ~9 months. Super rare. Not sure how to debug it...

A restart always fixes it, but that's not ideal. 😅

Any more reports/info could be useful.

wesbland commented 1 year ago

I did have the computer asleep, but it didn't go away after waking up.

SENTINELITE commented 1 year ago

I did have the computer asleep, but it didn't go away after waking up.

Yeah, that's what I've experienced, too. Hm...

jokalode commented 1 year ago

I had this again yesterday. I applied the Xcode time profiler to the process, in the hope of finding some clue about what was going on. Can't say that I could make much sense of it at first glance, and I couldn't analyse in depth due time constraints of my own. But I noticed that some hashing was going on, and some CFSetGetValue was called many times ...

For a more structured analysis, I recorded a 30 s time profile when the process was seemingly ok, and idling happily. It looks like the following stacktrace.

StreamDeck-Shortcuts
start_wqthread  
_pthread_wqthread   
_dispatch_workloop_worker_thread    
_dispatch_workloop_invoke   
_dispatch_lane_invoke   
_dispatch_lane_serial_drain 
_dispatch_client_callout    
_dispatch_call_block_and_release    
nw_connection_add_read_request_on_queue 
nw_endpoint_handler_service_reads   
nw_flow_service_reads   
nw_framer_protocol_get_input_frames 
nw_socket_get_input_frames(nw_protocol*, nw_protocol*, unsigned int, unsigned int, unsigned int, nw_frame_array_s*) 
__recvmsg   

Makes sense: Sitting and waiting for message frames to arrive.

Now I am waiting for the event to occur again, to be able to have a look at the pathological case.

SENTINELITE commented 1 year ago

@jokalode Wow, thanks for this! I truly appreciate you digging into it, as I really have no idea how to debug it.

If you find more concrete info, perhaps we can find the culprit:

The plug-in uses the following package. if it has something to do with this, I'll make sure to submit a PR/big report.

Anyways, I'm willing to dig more into it, with some direction. I appreciate the you taking the time to reach out again!

jokalode commented 1 year ago

And here is a stacktrace for a pathological case:

125361  StreamDeck-Shortcuts
125361  start_wqthread  
125361  _pthread_wqthread   
125361  _dispatch_workloop_worker_thread    
125361  _dispatch_lane_invoke   
125361  _dispatch_lane_serial_drain 
125361  _dispatch_client_callout    
125361  _dispatch_call_block_and_release    
125361  thunk for @escaping @callee_guaranteed @Sendable (@guaranteed NSURLSessionWebSocketMessage?, @guaranteed Error?) -> ()  
125361  closure #1 in NSURLSessionWebSocketTask.receive(completionHandler:) 
125361  0x1082f7a80 // application
125361  protocol witness for Subscriber.receive(_:) in conformance Publishers.SubscribeOn<A, B>.Inner<A1>   
125361  Publishers.SubscribeOn.Inner.receive(_:)    
125361  Publishers.CompactMap.Inner.receive(_:) 
125361  protocol witness for Subscriber.receive(_:) in conformance Publishers.TryMap<A, B>.Inner<A1>    
125361  Publishers.TryMap.Inner.receive(_:) 
125361  protocol witness for Subscriber.receive(_:) in conformance Publishers.Catch<A, B>.Inner<A1>.UncaughtS   
125361  Publishers.Catch.Inner.UncaughtS.receive(_:)    
125361  Publishers.Catch.Inner.receivePre(_:)   
125361  Publishers.CompactMap.Inner.receive(_:) 
125361  protocol witness for Subscriber.receive(_:) in conformance Subscribers.Sink<A, B>   
125361  Subscribers.Sink.receive(_:)    
125361  0x1082ef030 // application  
125361  0x1082e9f80 // application
125361  0x1082ea450 // application
125361  0x1082a6c80 // application
125361  0x1082b8d00 // application
125361  0x1082ba240 // application
125130  -[NSConcreteTask waitUntilExit] 
116946  CFRunLoopRunSpecific    
63386   __CFRunLoopCopyMode 
36272   CFSetGetValue   
23572   CFBasicHashFindBucket   
6682    CFEqual 

Until _dispatch_call_block_and_release we see the same call stack as in the healthy sample, which was waiting for message frames to arrive. So I guess that a message frame did arrive, and this pathological behaviour starts when or after processing that message. This assumption is backed by closure #1 in NSURLSessionWebSocketTask.receive.

Then we see the Combine framework in action: publishing, compact-mapping, try-mapping, catching, compact-mapping again, finally delivering to the Sink.

The pathological behaviour starts after [NSConcreteTask waitUntilExit]: There the application gets into an endless loop. As far as I can see, this concerns the CoreFoundation framework. Misconfigured run loop mode? Fails on something and falls back to itself? A repeating timer that reschedules itself immediately? I can only guess.

@SENTINELITE, hope this gives you an idea where to look. In the meantime, I'll try to build a local version.

jondkinney commented 1 year ago

Similar issue here CleanShot 2023-11-01 at 13 35 39