CC: Tweaked

CC: Tweaked

57M Downloads

Allocated a negative number of bytes

J2-Tech opened this issue · 9 comments

commented

Minecraft Version

1.20.x

Version

1.109.6

Details

Getting some spam on my arclight server logs :

Ex:
[05:25:28 WARN] [d.c.c.c.c.ComputerThread]: Allocated a negative number of bytes (-3093480)!
[06:52:38 WARN] [d.c.c.c.c.ComputerThread]: Allocated a negative number of bytes (-3241872)!
[07:08:06 WARN] [d.c.c.c.c.ComputerThread]: Allocated a negative number of bytes (-3219152)!
[07:54:31 WARN] [d.c.c.c.c.ComputerThread]: Allocated a negative number of bytes (-2905632)!
[08:29:22 WARN] [d.c.c.c.c.ComputerThread]: Allocated a negative number of bytes (-3221248)!

here are part of my server logs
log-part.log

commented

I seem to also be having this error in my logs. Not sure what exactly could be causing it since the programs the computers are running are made by a friend of mine. As far as i know we only have pc's interacting with create train stations and such.

commented

Created after commenting on #1672

commented

Would you be able to upload your full logs? They tend to include some other information that is useful for debugging!

commented

Yes, here they are. i wanted to make sure no ips or usernames were in there, but i think it's OK
debug.log

commented

Yeah, this is all very odd - I cannot see any reason why this would happen. I've added some additional logging in the latest CC:T release. Would you be able to update to 1.110.0 and upload your logs again? Thanks, and sorry!

commented

https://mclo.gs/u7wI7TN#L6007 this was taken with 1.110.1

commented

Here are two of the main programs running on multiple turtles / computers
https://pastebin.com/G6CGbhAt

https://pastebin.com/1Lgvt4dz

I'm also running This on two or three computers with massive ammounts of storage connected to the network.

https://github.com/SquidDev-CC/artist

commented

Thanks for the extra info both!

Allocated a negative number of bytes (-2667800)!
    Previous measurement at t=2667975172513365 on Thread #203 = 22172296600
     Current measurement at t=2667975172784822 on Thread #203 = 22169628800
Allocated a negative number of bytes (-3753488)!
    Previous measurement at t=2672289821893707 on Thread #203 = 59493198512
     Current measurement at t=2672289822061122 on Thread #203 = 59489445024
Allocated a negative number of bytes (-4186952)!
    Previous measurement at t=2674160200447684 on Thread #203 = 81195106984
     Current measurement at t=2674160200587238 on Thread #203 = 81190920032
Allocated a negative number of bytes (-454672)!
    Previous measurement at t=3513475356971 on Thread #174 = 982904520
     Current measurement at t=3513475583092 on Thread #174 = 982449848

This is very odd. We're definitely not measuring the wrong thread, so the allocation counter is sometimes going backwards. The two measurements are between 100µs and 300µs apart, which is short, but not so short I'd expect it to be an issue.

Taking a look at the implementation of Thread::cooked_allocated_bytes, there are several cases where the value might decrease (for instance, when fetching this value while the TLAB is being cleared). But this is happening surprisingly often for what feels like it should be a rare race condition.

commented

debug.log
A little late on this but here is the debug log with the extra logging you've added