CSM icon indicating copy to clipboard operation
CSM copied to clipboard

Performance issues up to complete stillstand

Open luuuke opened this issue 4 years ago • 5 comments

Describe the bug Host experiences first severe performance problems up to complete still stand of the game (no income, cars on roads are not moving, but UI still operating) after bus stops were added (and only if a client is connected). Log got continously spammed with *TransactionCommand messages. See Log 1 below.

Some time later in a new game (without) bus stops the same symptoms occured, now the Log got spammed with PlayerLocationCommand. See Log 2 below.

Addendum: After having the same issue again today, I deleted the log-current.txt file while the game was running/stuttering. Then it ran smoothly again. No idea, whats going on there.

Log files were later the size of some megabytes. (Though, the file, which got recreated after I deleted it, even had the size of 10 MB, but no problems were observed.)

To Reproduce See above.

Additional context

Log 1:

[17:43:21.4273] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:21.4681] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:21.5070] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:21.5429] [1905.6.0.0] [Debug] Received FinishTransactionCommand ... and on and on ... [17:43:23.5828] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:23.6177] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:23.6558] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:23.6920] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:23.7298] [1905.6.0.0] [Debug] Received TransportLineAddStopCommand [17:43:23.7646] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:23.8059] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:23.8421] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:23.8811] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:23.9213] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:23.9612] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.0011] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.0361] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.0743] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.1097] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.1448] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.1793] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.2130] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.2539] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.3043] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.3442] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.3890] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:24.4339] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.4768] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.5187] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:24.5646] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.6194] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.6543] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.6882] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:24.7242] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.7630] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:24.7979] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:24.8368] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:24.8737] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.9126] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:24.9506] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:24.9874] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.0243] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:25.0573] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:25.0932] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:25.1291] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.1690] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:25.2069] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:25.2418] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:25.2777] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:25.3166] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:25.3555] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:25.3953] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.4322] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:25.4653] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:25.5022] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:25.5451] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:25.5770] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:25.6089] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.6458] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:25.6792] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:25.7101] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:25.7421] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:25.7810] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.8188] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.8527] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.8867] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.9206] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.9555] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:25.9974] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:26.0313] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:26.0692] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:26.1041] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:26.1386] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:26.1735] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:26.2134] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:26.2474] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:26.2789] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:26.3188] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:26.3547] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:26.3963] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:26.4312] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:26.4652] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:26.5006] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:26.5415] [1905.6.0.0] [Debug] Received TransportLineSyncCommand ... and on an on ... [17:43:31.6083] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:31.6452] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:31.6811] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:31.7140] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:31.7539] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:31.7898] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:31.8287] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:31.8686] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:31.9145] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:31.9504] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:31.9853] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:32.0192] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:32.0561] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:32.0900] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:32.1269] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.1648] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:32.1997] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:32.2337] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:32.2715] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.3094] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.3483] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.3862] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.4291] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.4710] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.5069] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.5444] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.5803] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.6187] [1905.6.0.0] [Debug] Received PlayerLocationCommand [17:43:32.6536] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:32.6905] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:32.7274] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:32.7623] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:32.8002] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:32.8371] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:32.8740] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:32.9089] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:32.9448] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:32.9787] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:33.0146] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:33.0485] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:33.0865] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:33.1223] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:33.1572] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:33.1901] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:33.2241] [1905.6.0.0] [Debug] Received TransportLineSyncCommand ... maaany more of those, truncated a little more here ... [17:43:36.9467] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:36.9806] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:37.0145] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:37.0504] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:37.0853] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:37.1202] [1905.6.0.0] [Debug] Received TransportLineTempCommand [17:43:37.1521] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:37.1880] [1905.6.0.0] [Debug] Received SegmentSeedUpdateCommand [17:43:37.2229] [1905.6.0.0] [Debug] Received FinishTransactionCommand [17:43:37.2578] [1905.6.0.0] [Debug] Received TransportLineSyncCommand [17:43:37.2938] [1905.6.0.0] [Debug] Received FinishTransactionCommand ...

Log 2:

[22:03:31.8719] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:31.9401] [1905.6.0.0] [Debug] Received BuildingCreateCommand [22:03:32.0099] [1905.6.0.0] [Debug] Received FinishTransactionCommand [22:03:32.0806] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:32.1505] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:32.2181] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:32.2888] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:32.3498] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:32.4146] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:32.4794] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:03:32.5413] [1905.6.0.0] [Debug] Received PlayerLocationCommand ... now only PlayerLocationCommand for ages. [22:07:10.6834] [1905.6.0.0] [Debug] Received PlayerLocationCommand [22:07:10.7562] [1905.6.0.0] [Debug] Received PlayerLocationCommand ... here my friend disconnects and I quit the game as nothing is happening anymore. [22:07:40.0125] [1905.6.0.0] [Info] Player FRIEND lost connection! Reason: RemoteConnectionClose [22:07:40.0923] [1905.6.0.0] [Debug] Sending ClientDisconnectCommand to all clients [22:08:45.0888] [1905.6.0.0] [Info] Server stopped. [22:08:48.8968] [1905.6.0.0] [Info] Unpatching Harmony... [22:08:49.1936] [1905.6.0.0] [Info] Destruction complete! [22:08:49.2575] [1905.6.0.0] [Info] Unpatching Harmony...

luuuke avatar Dec 18 '19 19:12 luuuke

It got better when you deleted the log file? I'll look into splitting the log file after a certain size, and having an option to disable logging (at least the debug logs).

DominicMaas avatar Dec 22 '19 21:12 DominicMaas

It might not have to directly do with the log size, but with how often we are writing to the log. I think it would be a good idea to have an option that enables debug logging, but keep it disabled by default.

Seems like even a small map with a few roads generates about 1KB of logs per second.

Is your game installed on a HDD by any chance? I can replicate the issue on my PC (with the game on an external HDD), but my Surface is fine (internal SSD).

DominicMaas avatar Dec 22 '19 21:12 DominicMaas

It got completely fixed, yes. But I’m right now really unsure if this is correlation or causation. As described, after deleting the (maybe 3 MB big) log file it grew from 0 to 10 MB but the game still ran fine.

I’m not near my PC over the Christmas holidays, but I’m fairly sure it’s installed on my internal HDD.

luuuke avatar Dec 24 '19 11:12 luuuke

I ran into a similar issue. The issue mostly occurred when using faster speeds (accelerate time). With a city of +35k inhabitants the faster speeds caused microfreezes every few seconds. This seems to not be a big issue at slower speeds.

13hannes11 avatar Jul 19 '22 21:07 13hannes11

I ran into a similar issue. The issue mostly occurred when using faster speeds (accelerate time). With a city of +35k inhabitants the faster speeds caused microfreezes every few seconds. This seems to not be a big issue at slower speeds.

I'd like to bump this bug report if possible! Newcomer to using CS:MP and having a blast with it, so thank you for the hard work for starters! I'm very much experiencing the above too with very hard freezes nearly every 15/20 secs with only the UI being operational and all traffic/other frozen in place, this occurs when playing with 2/3x speed, and very, very rarely when using 1x speed. (MacOS M1 16GB with Internal SSD and i9, RTX3070 with Internal SSD tested also with same issue on both)

iKrypto avatar Sep 20 '23 17:09 iKrypto