I've got the same problem (starts then instantly closes) and there does not appear to be any sort of space before the command. The only modifications I made were to the ram thing, setting it to -Xms3072m -Xmx3072m (although it didn't work with the default set in the first post either).
JVM Arguments for Modded Minecraft (Updated 12/30/13)
- Thread starter Eyamaz
- Start date
-
The FTB Forum is now read-only, and is here as an archive. To participate in our community discussions, please join our Discord! https://ftb.team/discord
I've got the same problem (starts then instantly closes) and there does not appear to be any sort of space before the command. The only modifications I made were to the ram thing, setting it to -Xms3072m -Xmx3072m (although it didn't work with the default set in the first post either).
Raised PermGen to 150m
He tried direwolf20 pack but still crash on singleplayer when generating new world(without bioms o plenty world gen), could you please examine the above crashlog what is happening. I used -XX:+PrintHeapAtGC -XX:+PrintGCDetails Flags like you said. Thanks.
http://pastebin.com/y4RRZuam
Alright, looking at that ...
Looks like at 21:38, you started a single player game, it takes about 25 seconds to load the save and put you in, then rendering starts, it seems slow, and then
About a 10 second gap during saving before it actually starts to shut down. ...
I'm seeing a lot of things like this at world start and shut down. Note that it says the real time is more than a second?
I see this being slow, but I don't see any errors or other problems. What exactly went wrong here?
Sound failed to initialize, but I can't do anything to help with that.
Looks like at 21:38, you started a single player game, it takes about 25 seconds to load the save and put you in, then rendering starts, it seems slow, and then
Code:
2013-12-10 21:38:37 [INFO] [Minecraft-Server] Saving chunks for level 'New World'/Nether
2013-12-10 21:38:37 [INFO] [Minecraft-Server] Saving chunks for level 'New World'/The Moo Moo Farm
2013-12-10 21:38:46 [INFO] [ForgeModLoader] Unloading dimension 0
2013-12-10 21:38:46 [INFO] [ForgeModLoader] Unloading dimension -1
2013-12-10 21:38:46 [INFO] [ForgeModLoader] Unloading dimension -31About a 10 second gap during saving before it actually starts to shut down. ...
Code:
[Full GC[Tenured: 537255K->537262K(699072K), 1.2100942 secs] 540779K->537262K(1013632K), [Perm : 66253K->66253K(153600K)], 1.2101579 secs] [Times: user=1.20 sys=0.00, real=1.21 secs]I'm seeing a lot of things like this at world start and shut down. Note that it says the real time is more than a second?
I see this being slow, but I don't see any errors or other problems. What exactly went wrong here?
Sound failed to initialize, but I can't do anything to help with that.
Oh, wait.
Are you getting an out of memory error and crash?
Blech.
Minecraft is forcing a total of three full collections during startup. You're taking 4+ seconds. Java is probably thinking it's too much time for garbage collection.
Try adding " -XX:+DisableExplicitGC ", and see if that helps.
Are you getting an out of memory error and crash?
Blech.
Minecraft is forcing a total of three full collections during startup. You're taking 4+ seconds. Java is probably thinking it's too much time for garbage collection.
Try adding " -XX:+DisableExplicitGC ", and see if that helps.
He is getting "Shut-downing Internal server" and the http://i.imgur.com/X1PtHUi.png, so no crash. He will try to add that flag.
Btw, we tested on server and it works fine, but if he uses NEI client start's to be unresponsive, and then he must kill minecraft... Very annoying. Other wise he has like 50-70 fps on server..[DOUBLEPOST=1386711527][/DOUBLEPOST]What is realTime?
Btw, we tested on server and it works fine, but if he uses NEI client start's to be unresponsive, and then he must kill minecraft... Very annoying. Other wise he has like 50-70 fps on server..[DOUBLEPOST=1386711527][/DOUBLEPOST]What is realTime?
Last edited:
Real time: How much actual time was spent on the operation.
[Full GC[Tenured: 537255K->537262K(699072K), 1.2100942 secs] 540779K->537262K(1013632K), [Perm : 66253K->66253K(153600K)], 1.2101579 secs] [Times: user=1.20 sys=0.00, real=1.21 secs]
Real=1.21 secs means that a collection took 1.21 seconds.
Logging in forces 3 collections -- as far as I can tell, one for connecting to the server, one for a level change, and I have no idea why the third happens.
Mojang is forcing full GC's. Bad, in general. Given that I've seen 90+ seconds once, and 30+ seconds multiple times, in a client/server setup, that's the sort of "If it happens to the client, you DC the client; if it happens to the server, you DC everyone". (No, the server doesn't -- as far as I know -- have a forced GC, but it will eventually have to GC on it's own, and that will lag every player.)
Worse, if you go into a new dimension, and are locked out from taking actions for 10-15 seconds, while hostiles are attacking you on the server, ...
is that wise to do for a server environment?
on another note.
Code:
Java.CustomOpts=-Xms2048m -Xmx5120m -XX:PermSize=256m -XX:ReservedCodeCacheSize=512m -XX:NewRatio=4 -XX:SurvivorRatio=3 -XX:TargetSurvivorRatio=80 -XX:MaxTenuringThreshold=8 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:SoftRefLRUPolicyMSPerMB=0 -XX:MaxGCPauseMillis=20 -XX:GCPauseIntervalMillis=250 -XX:MaxGCMinorPauseMillis=7 -XX:+CMSClassUnloadingEnabled -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=50 -XX:+BindGCTaskThreadsToCPUs -XX:+TieredCompilation -XX:Tier0ProfilingStartPercentage=0 -XX:Tier3InvocationThreshold=3 -XX:Tier3MinInvocationThreshold=2 -XX:Tier3CompileThreshold=2 -XX:Tier3BackEdgeThreshold=10 -XX:Tier4InvocationThreshold=4 -XX:Tier4MinInvocationThreshold=3 -XX:Tier4CompileThreshold=2 -XX:Tier4BackEdgeThreshold=8 -XX:TieredCompileTaskTimeout=5000 -XX:Tier3DelayOn=50 -XX:Tier3DelayOff=25 -XX:+UseFastEmptyMethods -XX:-DontCompileHugeMethods -XX:+AlwaysCompileLoopMethods -XX:+CICompilerCountPerCPU -XX:+UseStringCache -XX:+UseNUMAno Idea why it works on the server, but it works. regardless, I'm going to re do that the xms/xmx. but I am noticing one thing. when a player is going to and from mystcaft portals. there is a 1min delay before the player can interact with the world again. Is this the garbage collection at play?
A one minute delay after using a mystcraft portal?
Let me see if I understand this correctly:
User goes through the portal.
They see the world displayed on their screen.
They can wander around, and try to interact.
But it takes a minute before anything actually does happen.
And, this is in a server, not single player.
Is that correct?
Client is seeing stuff, and trying to interact, but nothing is happening.
For 60 seconds?!? Please verify, more than 30?
I seriously want to see the server's normal log, and garbage collection log, for that time period. Not the whole thing, just about a minute or two before, and that during, until the player can interact. Thanks.
Let me see if I understand this correctly:
User goes through the portal.
They see the world displayed on their screen.
They can wander around, and try to interact.
But it takes a minute before anything actually does happen.
And, this is in a server, not single player.
Is that correct?
Client is seeing stuff, and trying to interact, but nothing is happening.
For 60 seconds?!? Please verify, more than 30?
I seriously want to see the server's normal log, and garbage collection log, for that time period. Not the whole thing, just about a minute or two before, and that during, until the player can interact. Thanks.
ok I grabbed a stopwatch and timed it. its 25~ sec. but still that is a way too long of a delay.
clients are unmodified by default to keep things simple for my player base.
tested with modified client aka the ATlauncher its 35~sec.
this does not just happen on portal hops. this happens as soon as you login as well.
Server is MCPC+ but has happened with just straight forge. I just changed over to MCPC to see if that fixed the problem.
atm, I can only pull data off the client. I have to restart the server that have 2 other players currently on.
Let me see if I understand this correctly:
User goes through the portal. yes
They see the world displayed on their screen. yes
They can wander around, and try to interact. yes
But it takes a minute before anything actually does happen. ok 30 sec
And, this is in a server, not single player. server
Code:
[20:29:18 INFO]: Client> 2013-12-10 20:29:18 [INFO] [STDOUT] OpenAL initialized.
[20:29:18 INFO]: Client> 88.725: [GC88.725: [ParNew: 325796K->83840K(335552K), 0.1183602 secs] 817013K->609688K(2013312K), 0.1184539 secs] [Times: user=0.33 sys=0.02, real=0.12 secs]
[20:29:18 INFO]: Client> 2013-12-10 20:29:18 [INFO] [STDOUT]
[20:29:26 INFO]: Client> 2013-12-10 20:29:26 [INFO] [ForgeModLoader] InvTweaks: net.minecraft.client.gui.GuiTextField
[20:29:26 INFO]: Client> 2013-12-10 20:29:26 [INFO] [ForgeModLoader] InvTweaks: successfully transformed setFocused/func_73796_b
[20:29:27 INFO]: Client> 97.558: [GC97.558: [ParNew: 285467K->56847K(335552K), 0.0509957 secs] 811316K->582695K(2013312K), 0.0510760 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:29:27 INFO]: Client> 97.609: [GC [1 CMS-initial-mark: 525848K(1677760K)] 582695K(2013312K), 0.0114691 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[20:29:27 INFO]: Client> 97.621: [CMS-concurrent-mark-start]
[20:29:27 INFO]: Client> 98.064: [CMS-concurrent-mark: 0.442/0.442 secs] [Times: user=0.42 sys=0.02, real=0.44 secs]
[20:29:27 INFO]: Client> 98.064: [CMS-concurrent-preclean-start]
[20:29:27 INFO]: Client> 98.069: [CMS-concurrent-preclean: 0.005/0.005 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[20:29:28 INFO]: Client> 98.069: [GC[YG occupancy: 56847 K (335552 K)]98.069: [Rescan (parallel) , 0.0043716 secs]98.074: [weak refs processing, 0.0042960 secs]98.078: [class unloading, 0.0993570 secs]98.177: [scrub symbol table, 0.0216999 secs]98.199: [scrub string table, 0.0018804 secs] [1 CMS-remark: 525848K(1677760K)] 582695K(2013312K), 0.3798439 secs] [Times: user=0.36 sys=0.02, real=0.38 secs]
[20:29:28 INFO]: Client> 98.449: [CMS-concurrent-sweep-start]
[20:29:28 INFO]: Client> 98.637: [CMS-concurrent-sweep: 0.188/0.188 secs] [Times: user=0.33 sys=0.05, real=0.19 secs]
[20:29:28 INFO]: Client> 98.637: [CMS-concurrent-reset-start]
[20:29:28 INFO]: Client> 2013-12-10 20:29:28 [INFO] [Minecraft-Client] Connecting to dusto.homedns.org, 25566
[20:29:28 INFO]: Client> 98.654: [CMS-concurrent-reset: 0.017/0.017 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
[20:29:28 INFO]: Client> 2013-12-10 20:29:28 [INFO] [MapWriter] connection opened to remote server: dusto.homedns.org 25566
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [STDOUT] Setting up custom skins
[20:29:31 INFO]: Client> 101.873: [GC101.873: [ParNew: 224590K->66567K(335552K), 0.0657441 secs] 599639K->441616K(2013312K), 0.0658339 secs] [Times: user=0.22 sys=0.00, real=0.07 secs]
[20:29:31 INFO]: Client> 101.939: [GC [1 CMS-initial-mark: 375049K(1677760K)] 441616K(2013312K), 0.0216408 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
[20:29:31 INFO]: Client> 101.961: [CMS-concurrent-mark-start]
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [ForgeModLoader] [Modstats] Updates found: Modular Force Field System (3.5.0).
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [Minecraft-Client] [CHAT] Updates found: Modular Force Field System (3.5.0).
[20:29:32 INFO]: Client> 102.459: [CMS-concurrent-mark: 0.470/0.499 secs] [Times: user=1.08 sys=0.05, real=0.50 secs]
[20:29:32 INFO]: Client> 102.459: [CMS-concurrent-preclean-start]
[20:29:32 INFO]: Client> 102.465: [CMS-concurrent-preclean: 0.006/0.006 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[20:29:32 INFO]: Client> 102.465: [CMS-concurrent-abortable-preclean-start]
[20:29:37 INFO]: Client> CMS: abort preclean due to time 107.666: [CMS-concurrent-abortable-preclean: 3.294/5.201 secs] [Times: user=3.35 sys=0.00, real=5.20 secs]
[20:29:37 INFO]: Client> 107.666: [GC[YG occupancy: 88248 K (335552 K)]107.666: [Rescan (parallel) , 0.0073352 secs]107.674: [weak refs processing, 0.0000676 secs]107.674: [class unloading, 0.0416197 secs]107.716: [scrub symbol table, 0.0217487 secs]107.737: [scrub string table, 0.0016772 secs] [1 CMS-remark: 375049K(1677760K)] 463297K(2013312K), 0.0871786 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
[20:29:37 INFO]: Client> 107.754: [CMS-concurrent-sweep-start]
[20:29:37 INFO]: Client> 107.914: [CMS-concurrent-sweep: 0.160/0.160 secs] [Times: user=0.19 sys=0.00, real=0.16 secs]
[20:29:37 INFO]: Client> 107.914: [CMS-concurrent-reset-start]
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [GraviGun] [2.0.0] Sending client info to server
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [PortalGun] [2.0.1] Sending client info to server
[20:29:37 INFO]: Client> 107.926: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [MapWriter] onClientLoggedIn: dimension = 0
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [MapWriter] generating block colours
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] generating block map colours from textures
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] created new MwTexture from GL texture id 8 (2048x1024) (2097152 pixels)
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] processed 3199 block textures, 11481 skipped, 348 exceptions
[20:29:38 INFO]: Client> 108.578: [GC108.578: [ParNew: 318279K->51694K(335552K), 0.0400100 secs] 677843K->411258K(2013312K), 0.0400984 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [Minecraft-Client] [CHAT] ZexMaxwell001 joined the game.
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [ForgeModLoader] [THAUMCRAFT] Client received server config settings.
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [ThermalExpansion] Received Server Configs...
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [STDOUT] Setting up custom skins
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.multipart.nei.NEI_MicroblockConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] IC2 NEI Submodule initialized
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded ic2.neiIntegration.core.NEIIC2Config
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.wirelessredstone.addons.NEIWirelessAddonConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded thermalexpansion.plugins.nei.NEIThermalExpansionConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] DRAGONAPI: Loading NEI Compatibility!
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded Reika.DragonAPI.NEI_APIConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.enderstorage.internal.NEIEnderStorageConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded factorization.nei.NEI_FactorizationInputConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded factorization.nei.NEI_FactorizationRecipeConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded shedar.mods.ic2.nuclearcontrol.crossmod.nei.NEINuclearControlConfig
[20:29:43 INFO]: Client> 113.271: [GC113.271: [ParNew: 303406K->83840K(335552K), 0.0495097 secs] 662970K->444835K(2013312K), 0.0495954 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidBiomass
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidBiofuel
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidSeedOil
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidJuice
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidHoney
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidMead
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidGlass
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidIce
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidMilk
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] Loaded mods.neiplugins.NEIPluginsConfig
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] ROTARYCRAFT: Loading NEI Compatibility!
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] ROTARYCRAFT: Hiding technical blocks from NEI!
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] Loaded Reika.RotaryCraft.ModInterface.NEI.NEI_RotaryConfig
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [ForgeModLoader] InvTweaks: codechicken.enderstorage.storage.item.ContainerEnderItemStorage
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [Minecraft-Client] [CHAT] [Server] Welcome back, ZexMaxwell001
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [Minecraft-Client] [CHAT] WELCOME!
[20:29:44 INFO]: Client> 115.067: [GC115.067: [ParNew: 325053K->73139K(335552K), 0.0645568 secs] 686048K->443775K(2013312K), 0.0646612 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:29:45 INFO]: Client> 2013-12-10 20:29:45 [INFO] [Minecraft-Client] [CHAT] A new version of Biomes O Plenty is available: v1.1.2 for Minecraft 1.6.4
[20:29:45 INFO]: Client> 115.950: [GC115.950: [ParNew: 316428K->74646K(335552K), 0.0598469 secs] 687065K->453539K(2013312K), 0.0599360 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
[20:29:47 INFO]: Client> 118.039: [GC118.039: [ParNew: 326358K->68520K(335552K), 0.0696180 secs] 705251K->456039K(2013312K), 0.0697079 secs] [Times: user=0.25 sys=0.00, real=0.07 secs]
[20:29:55 INFO]: Client> 125.534: [GC125.534: [ParNew: 312066K->67140K(335552K), 0.0526373 secs] 699586K->459076K(2013312K), 0.0527206 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
[20:30:02 INFO]: Client> 132.761: [GC132.761: [ParNew: 318852K->65542K(335552K), 0.0499674 secs] 710788K->458613K(2013312K), 0.0500458 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:30:03 INFO]: Client> 2013-12-10 20:30:03 [INFO] [GraviGun] [2.0.0] Received world props from server.
[20:30:03 INFO]: Client> 2013-12-10 20:30:03 [INFO] [PortalGun] [2.0.1] Received world props from server.
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] Inserted super call into axm.c
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] computercraft: Searching for RedPowerWorld...
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] computercraft: RedPowerWorld not found.
[20:30:05 INFO]: Client> 135.994: [GC135.994: [ParNew: 317254K->78610K(335552K), 0.0699348 secs] 710325K->478566K(2013312K), 0.0700251 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:30:08 INFO]: Client> 138.425: [GC138.425: [ParNew: 330322K->80724K(335552K), 0.0618847 secs] 730278K->481422K(2013312K), 0.0622287 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
[20:30:10 INFO]: Client> 2013-12-10 20:30:10 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:30:11 INFO]: Client> 141.427: [GC141.427: [ParNew: 332436K->50975K(335552K), 0.0645983 secs] 733134K->456076K(2013312K), 0.0646850 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
[20:30:11 INFO]: Client> 141.496: [GC141.496: [ParNew: 52799K->35620K(335552K), 0.0519046 secs] 457901K->451716K(2013312K), 0.0519983 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/grindertex.png
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Empty or invalid rednet blacklist entry found. Not adding to rednet blacklist.
[20:30:12 INFO]: Client> 143.074: [GC143.074: [ParNew: 274100K->34279K(335552K), 0.0425758 secs] 690195K->457172K(2013312K), 0.0426653 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to Textures/Items/items2.png
[20:30:13 INFO]: Client> 2013-12-10 20:30:13 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/actex.png
[20:30:13 INFO]: Client> 2013-12-10 20:30:13 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/dc.png
[20:30:14 INFO]: Client> 145.196: [GC145.196: [ParNew: 275714K->41101K(335552K), 0.0439535 secs] 698607K->465207K(2013312K), 0.0440249 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
[20:30:22 INFO]: Client> 152.949: [GC152.949: [ParNew: 292813K->43465K(335552K), 0.0454871 secs] 716919K->468520K(2013312K), 0.0455732 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
[20:30:37 INFO]: Client> 168.082: [GC168.082: [ParNew: 294225K->61822K(335552K), 0.0494187 secs] 719280K->487275K(2013312K), 0.0494967 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:30:50 INFO]: Client> 181.121: [GC181.121: [ParNew: 313534K->83840K(335552K), 0.0709885 secs] 738987K->514743K(2013312K), 0.0710814 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:30:57 INFO]: Client> 2013-12-10 20:30:57 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:30:59 INFO]: Client> 189.813: [GC189.813: [ParNew: 335499K->44552K(335552K), 0.0552860 secs] 766402K->477856K(2013312K), 0.0553647 secs] [Times: user=0.17 sys=0.00, real=0.06 secs]
[20:31:22 INFO]: Client> 212.495: [GC212.495: [ParNew: 295956K->64637K(335552K), 0.0527517 secs] 729260K->503012K(2013312K), 0.0528438 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:31:41 INFO]: Client> 232.028: [GC232.028: [ParNew: 316349K->82405K(335552K), 0.0561131 secs] 754724K->520782K(2013312K), 0.0561910 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [Minecraft-Client] Stopping!
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [STDOUT]
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [STDOUT] SoundSystem shutting down...
[20:31:49 INFO]: Client> 2013-12-10 20:31:49 [INFO] [STDOUT] Author: Paul Lamb, www.paulscode.com
[20:31:49 INFO]: Client> 2013-12-10 20:31:49 [INFO] [STDOUT]
[20:31:49 INFO]: Client> Heap
[20:31:49 INFO]: Client> par new generation total 335552K, used 235772K [0x0000000770000000, 0x0000000789990000, 0x0000000789990000)
[20:31:49 INFO]: Client> eden space 251712K, 60% used [0x0000000770000000, 0x00000007795c5a48, 0x000000077f5d0000)
[20:31:49 INFO]: Client> from space 83840K, 98% used [0x00000007847b0000, 0x00000007898296f0, 0x0000000789990000)
[20:31:49 INFO]: Client> to space 83840K, 0% used [0x000000077f5d0000, 0x000000077f5d0000, 0x00000007847b0000)
[20:31:49 INFO]: Client> concurrent mark-sweep generation total 1677760K, used 438376K [0x0000000789990000, 0x00000007f0000000, 0x00000007f0000000)
[20:31:49 INFO]: Client> concurrent-mark-sweep perm gen total 262144K, used 117784K [0x00000007f0000000, 0x0000000800000000, 0x0000000800000000)
[20:31:49 INFO]: Game ended with no troubles detected (exit code 0)ok this is the server log. I stated it as soon as I joined. done 2 book hops(linkbook) then one portal hop. no one else was online. just chunkloaders.
Code:
Console : 2013-12-10 20:54:13 [INFO] ZexMaxwell001[/75.121.155.245:18697] logged in with entity id 1426 at ([world] -1869.5362731553614, 73.0, 1470.5339756943285)
Console : 2013-12-10 20:54:14 [INFO] Loading Player: ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] Sending serverside check to: ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] [Server] Welcome back, ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] [CONSOLE->ZexMaxwell001] WELCOME!
Console : 222.085: [GC222.085: [ParNew: 324904K->67878K(335552K), 0.0732902 secs] 1049657K->792631K(2013312K), 0.0733933 secs] [Times: user=0.30 sys=0.00, real=0.07 secs]
Console : 224.332: [GC224.332: [ParNew: 319590K->83840K(335552K), 0.0645324 secs] 1044343K->808596K(2013312K), 0.0646450 secs] [Times: user=0.25 sys=0.00, real=0.06 secs]
Console : 226.952: [GC226.952: [ParNew: 335552K->82877K(335552K), 0.0709034 secs] 1060308K->823779K(2013312K), 0.0709899 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
Console : 2013-12-10 20:54:20 [INFO] [2.0.0] Recieved client info from ZexMaxwell001
Console : 2013-12-10 20:54:20 [INFO] [2.0.1] Recieved client info from ZexMaxwell001
Console : 229.724: [GC229.724: [ParNew: 334589K->69138K(335552K), 0.0460928 secs] 1075491K->810040K(2013312K), 0.0461930 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 232.440: [GC232.440: [ParNew: 320850K->83840K(335552K), 0.0477742 secs] 1061752K->825074K(2013312K), 0.0478636 secs] [Times: user=0.17 sys=0.00, real=0.05 secs]
Console : 235.167: [GC235.167: [ParNew: 335552K->68313K(335552K), 0.0453652 secs] 1076786K->810116K(2013312K), 0.0454580 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 237.879: [GC237.879: [ParNew: 320025K->83840K(335552K), 0.0427348 secs] 1061828K->825705K(2013312K), 0.0428205 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 240.586: [GC240.586: [ParNew: 335552K->65377K(335552K), 0.0409615 secs] 1077417K->807823K(2013312K), 0.0410441 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 2013-12-10 20:54:34 [INFO] <ZexMaxwell001> joined
Console : 243.193: [GC243.193: [ParNew: 317089K->45769K(335552K), 0.0658585 secs] 1059535K->817602K(2013312K), 0.0659411 secs] [Times: user=0.17 sys=0.01, real=0.07 secs]
Console : 245.927: [GC245.927: [ParNew: 297481K->18610K(335552K), 0.0241779 secs] 1069314K->794684K(2013312K), 0.0242687 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]
Console : 248.540: [GC248.540: [ParNew: 270322K->15306K(335552K), 0.0219110 secs] 1046396K->796165K(2013312K), 0.0220073 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 251.217: [GC251.217: [ParNew: 267018K->18031K(335552K), 0.0205961 secs] 1047877K->799013K(2013312K), 0.0206817 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 253.900: [GC253.900: [ParNew: 269743K->22761K(335552K), 0.0211418 secs] 1050725K->803811K(2013312K), 0.0212356 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:54:49 [WARNING] Trying to propagate invalid map data 0
Console : 256.575: [GC256.575: [ParNew: 274473K->27276K(335552K), 0.0241013 secs] 1055523K->808337K(2013312K), 0.0241921 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 259.288: [GC259.288: [ParNew: 278988K->30211K(335552K), 0.0229918 secs] 1060049K->811305K(2013312K), 0.0230852 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:54:53 [INFO] Sending serverside check to: ZexMaxwell001
Console : 261.639: [GC261.639: [ParNew: 281923K->76112K(335552K), 0.0571218 secs] 1063017K->857222K(2013312K), 0.0572164 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
Console : 263.417: [GC263.417: [ParNew: 327824K->83840K(335552K), 0.0565405 secs] 1108934K->865183K(2013312K), 0.0566235 secs] [Times: user=0.20 sys=0.00, real=0.06 secs]
Console : 265.862: [GC265.862: [ParNew: 335552K->83840K(335552K), 0.0565349 secs] 1116895K->880313K(2013312K), 0.0566295 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
Console : 2013-12-10 20:55:01 [INFO] <ZexMaxwell001> book hop
Console : 268.523: [GC268.523: [ParNew: 335552K->83840K(335552K), 0.0505809 secs] 1132025K->883316K(2013312K), 0.0506639 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
Console : 271.239: [GC271.239: [ParNew: 335552K->81429K(335552K), 0.0493930 secs] 1135028K->880906K(2013312K), 0.0494804 secs] [Times: user=0.23 sys=0.00, real=0.05 secs]
Console : 273.906: [GC273.906: [ParNew: 333141K->83840K(335552K), 0.0538194 secs] 1132618K->883317K(2013312K), 0.0539234 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 276.604: [GC276.604: [ParNew: 335552K->63326K(335552K), 0.0467529 secs] 1135029K->862803K(2013312K), 0.0468458 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 279.316: [GC279.316: [ParNew: 315038K->76728K(335552K), 0.0419614 secs] 1114515K->876286K(2013312K), 0.0420521 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 281.973: [GC281.973: [ParNew: 328440K->39926K(335552K), 0.0747425 secs] 1127998K->871788K(2013312K), 0.0748440 secs] [Times: user=0.22 sys=0.00, real=0.08 secs]
Console : 284.675: [GC284.675: [ParNew: 291638K->39681K(335552K), 0.0287978 secs] 1123500K->871793K(2013312K), 0.0288817 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
Console : 287.326: [GC287.326: [ParNew: 291393K->34214K(335552K), 0.0328946 secs] 1123505K->876914K(2013312K), 0.0329956 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 287.360: [GC [1 CMS-initial-mark: 842700K(1677760K)] 881856K(2013312K), 0.0162583 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
Console : 287.376: [CMS-concurrent-mark-start]
Console : 288.132: [CMS-concurrent-mark: 0.755/0.755 secs] [Times: user=0.97 sys=0.00, real=0.76 secs]
Console : 288.132: [CMS-concurrent-preclean-start]
Console : 288.140: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
Console : 288.140: [CMS-concurrent-abortable-preclean-start]
Console : 290.008: [GC290.008: [ParNew: 285926K->42912K(335552K), 0.0255789 secs] 1128626K->885765K(2013312K), 0.0256603 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
Console : 2013-12-10 20:55:24 [INFO] Sending serverside check to: ZexMaxwell001
Console : 291.522: [CMS-concurrent-abortable-preclean: 1.538/3.382 secs] [Times: user=3.54 sys=0.16, real=3.38 secs]
Console : 291.525: [GC[YG occupancy: 209260 K (335552 K)]291.525: [Rescan (parallel) , 0.0345622 secs]291.560: [weak refs processing, 0.0000796 secs]291.560: [class unloading, 0.1338067 secs]291.694: [scrub symbol table, 0.0194507 secs]291.713: [scrub string table, 0.0017156 secs] [1 CMS-remark: 842853K(1677760K)] 1052113K(2013312K), 0.4719684 secs] [Times: user=0.56 sys=0.00, real=0.47 secs]
Console : 291.998: [CMS-concurrent-sweep-start]
Console : 292.393: [CMS-concurrent-sweep: 0.394/0.395 secs] [Times: user=1.34 sys=0.08, real=0.39 secs]
Console : 292.393: [CMS-concurrent-reset-start]
Console : 292.417: [CMS-concurrent-reset: 0.025/0.025 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
Console : 292.433: [GC292.433: [ParNew: 294624K->61186K(335552K), 0.0473688 secs] 876609K->643191K(2013312K), 0.0474600 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 293.969: [GC293.969: [ParNew: 312898K->83840K(335552K), 0.0491615 secs] 894903K->665872K(2013312K), 0.0492526 secs] [Times: user=0.25 sys=0.00, real=0.05 secs]
Console : 296.393: [GC296.393: [ParNew: 335552K->83840K(335552K), 0.0535386 secs] 917584K->673583K(2013312K), 0.0536294 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 2013-12-10 20:55:29 [INFO] <ZexMaxwell001> bookhop
Console : 299.053: [GC299.054: [ParNew: 335552K->70217K(335552K), 0.0771160 secs] 925295K->695792K(2013312K), 0.0772033 secs] [Times: user=0.22 sys=0.05, real=0.08 secs]
Console : 2013-12-10 20:55:33 [INFO] Sending serverside check to: ZexMaxwell001
Console : 2013-12-10 20:55:33 [INFO] Sending serverside check to: ZexMaxwell001
Console : 301.613: [GC301.613: [ParNew: 321929K->47795K(335552K), 0.0295854 secs] 947504K->673370K(2013312K), 0.0296787 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 304.319: [GC304.319: [ParNew: 299507K->36828K(335552K), 0.0298718 secs] 925082K->662403K(2013312K), 0.0299942 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 307.020: [GC307.020: [ParNew: 288540K->32209K(335552K), 0.0271824 secs] 914115K->657784K(2013312K), 0.0272761 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
Console : 309.672: [GC309.672: [ParNew: 283921K->43622K(335552K), 0.0245499 secs] 909496K->669197K(2013312K), 0.0246522 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
Console : 312.424: [GC312.424: [ParNew: 295334K->24524K(335552K), 0.0245927 secs] 920909K->650099K(2013312K), 0.0247096 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:55:45 [INFO] <ZexMaxwell001> portal hop
Console : 315.125: [GC315.125: [ParNew: 276236K->30479K(335552K), 0.0236330 secs] 901811K->656480K(2013312K), 0.0237379 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 317.694: [GC317.694: [ParNew: 282191K->20044K(335552K), 0.0236215 secs] 908192K->650199K(2013312K), 0.0237272 secs] [Times: user=0.12 sys=0.00, real=0.02 secs]
Console : 320.277: [GC320.277: [ParNew: 271756K->17605K(335552K), 0.0198423 secs] 901911K->647842K(2013312K), 0.0199429 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 322.879: [GC322.879: [ParNew: 269317K->24899K(335552K), 0.0213263 secs] 899554K->655872K(2013312K), 0.0214214 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 324.683: [GC324.683: [ParNew: 276611K->56369K(335552K), 0.0412063 secs] 907584K->687383K(2013312K), 0.0413022 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 327.217: [GC327.217: [ParNew: 308081K->76712K(335552K), 0.0464528 secs] 939095K->707765K(2013312K), 0.0465573 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 329.925: [GC329.925: [ParNew: 328424K->82730K(335552K), 0.0446769 secs] 959477K->713819K(2013312K), 0.0447766 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 2013-12-10 20:56:03 [INFO] <ZexMaxwell001> ending
Console : 332.589: [GC332.589: [ParNew: 334442K->83840K(335552K), 0.0455193 secs] 965531K->714955K(2013312K), 0.0456117 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 335.299: [GC335.299: [ParNew: 335552K->83840K(335552K), 0.0441440 secs] 966667K->714957K(2013312K), 0.0442330 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 337.915: [GC337.915: [ParNew: 335552K->65588K(335552K), 0.0369071 secs] 969366K->700461K(2013312K), 0.0370025 secs] [Times: user=0.14 sys=0.00, real=0.04 secs]
Console : 337.952: [GC337.953: [ParNew: 70503K->54818K(335552K), 0.0385328 secs] 705377K->694833K(2013312K), 0.0386278 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
Console : 340.617: [GC340.617: [ParNew: 306530K->58612K(335552K), 0.0390032 secs] 946545K->703082K(2013312K), 0.0391021 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
Console : 343.272: [GC343.272: [ParNew: 310324K->25308K(335552K), 0.0513792 secs] 954794K->696442K(2013312K), 0.0514656 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 345.993: [GC345.993: [ParNew: 277020K->10763K(335552K), 0.0178913 secs] 948154K->682566K(2013312K), 0.0179923 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:56:19 [INFO] ZexMaxwell001 lost connection: disconnect.quitting
Console : 2013-12-10 20:56:19 [INFO] Connection reset
Console : 2013-12-10 20:56:19 [INFO] Unloading Player: ZexMaxwell001
Console : 2013-12-10 20:56:19 [INFO] eZexMaxwell001 left the game.
Console : 372.523: [GC372.523: [ParNew: 262475K->8486K(335552K), 0.0183698 secs] 934278K->680378K(2013312K), 0.0184636 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:57:06 [INFO] CONSOLE: Stopping the server..
Last edited:
Ok, the first issue is, only some of your mod initialization is happening before you log on. When you log on, you are having more initialization happen.
But look at the time stamps:
From :28 to :45, 17 seconds of initialization ...
From :45 to :03, 18 seconds of ... ???? What the heck is happening here? Clueless
Then, more initialization ...
Ok, that seems to be the last of the initialization messages.
And now it shuts down.
So, at least for the question, why is it taking so long to log in, the answer is, your mods are still getting ready. A better question is, since the general idea of "Lets get data from the server, and set up / initialize to that" makes sense, why does forge not have a recognition of this, with players in a "in-the-process-of-logging-on", but not yet actually logged on, state -- unable to interact or do anything on the server, until the client reports "I'm now fully initialized" to the
server?
During this time period (login), are you in the same situation of "able to move around, but not able to interact"?
---
Now, nothing in here is explaining the delay on mystcraft portals. By the time you get to using those, initialization of mods has finished.
Does it only happen on mystcraft portals?
What about mystcraft books?
What about nether portals?
Do you have any other dimension travel mods -- deep dark, promised land -- and do they also behave the same?[DOUBLEPOST=1386732555][/DOUBLEPOST]Ok, let me check your edit with the server logs ...
But look at the time stamps:
[20:29:28 INFO]: Client> 2013-12-10 20:29:28 [INFO] [Minecraft-Client] Connecting to dusto.homedns.org, 25566
[20:29:28 INFO]: Client> 98.654: [CMS-concurrent-reset: 0.017/0.017 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
[20:29:28 INFO]: Client> 2013-12-10 20:29:28 [INFO] [MapWriter] connection opened to remote server: dusto.homedns.org 25566
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [STDOUT] Setting up custom skins
[20:29:31 INFO]: Client> 101.873: [GC101.873: [ParNew: 224590K->66567K(335552K), 0.0657441 secs] 599639K->441616K(2013312K), 0.0658339 secs] [Times: user=0.22 sys=0.00, real=0.07 secs]
[20:29:31 INFO]: Client> 101.939: [GC [1 CMS-initial-mark: 375049K(1677760K)] 441616K(2013312K), 0.0216408 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
[20:29:31 INFO]: Client> 101.961: [CMS-concurrent-mark-start]
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [ForgeModLoader] [Modstats] Updates found: Modular Force Field System (3.5.0).
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [Minecraft-Client] [CHAT] Updates found: Modular Force Field System (3.5.0).
[20:29:32 INFO]: Client> 102.459: [CMS-concurrent-mark: 0.470/0.499 secs] [Times: user=1.08 sys=0.05, real=0.50 secs]
[20:29:32 INFO]: Client> 102.459: [CMS-concurrent-preclean-start]
[20:29:32 INFO]: Client> 102.465: [CMS-concurrent-preclean: 0.006/0.006 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[20:29:32 INFO]: Client> 102.465: [CMS-concurrent-abortable-preclean-start]
[20:29:37 INFO]: Client> CMS: abort preclean due to time 107.666: [CMS-concurrent-abortable-preclean: 3.294/5.201 secs] [Times: user=3.35 sys=0.00, real=5.20 secs]
[20:29:37 INFO]: Client> 107.666: [GC[YG occupancy: 88248 K (335552 K)]107.666: [Rescan (parallel) , 0.0073352 secs]107.674: [weak refs processing, 0.0000676 secs]107.674: [class unloading, 0.0416197 secs]107.716: [scrub symbol table, 0.0217487 secs]107.737: [scrub string table, 0.0016772 secs] [1 CMS-remark: 375049K(1677760K)] 463297K(2013312K), 0.0871786 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
[20:29:37 INFO]: Client> 107.754: [CMS-concurrent-sweep-start]
[20:29:37 INFO]: Client> 107.914: [CMS-concurrent-sweep: 0.160/0.160 secs] [Times: user=0.19 sys=0.00, real=0.16 secs]
[20:29:37 INFO]: Client> 107.914: [CMS-concurrent-reset-start]
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [GraviGun] [2.0.0] Sending client info to server
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [PortalGun] [2.0.1] Sending client info to server
[20:29:37 INFO]: Client> 107.926: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [MapWriter] onClientLoggedIn: dimension = 0
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [MapWriter] generating block colours
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] generating block map colours from textures
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] created new MwTexture from GL texture id 8 (2048x1024) (2097152 pixels)
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] processed 3199 block textures, 11481 skipped, 348 exceptions
[20:29:38 INFO]: Client> 108.578: [GC108.578: [ParNew: 318279K->51694K(335552K), 0.0400100 secs] 677843K->411258K(2013312K), 0.0400984 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [Minecraft-Client] [CHAT] ZexMaxwell001 joined the game.
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [ForgeModLoader] [THAUMCRAFT] Client received server config settings.
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [ThermalExpansion] Received Server Configs...
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [STDOUT] Setting up custom skins
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.multipart.nei.NEI_MicroblockConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] IC2 NEI Submodule initialized
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded ic2.neiIntegration.core.NEIIC2Config
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.wirelessredstone.addons.NEIWirelessAddonConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded thermalexpansion.plugins.nei.NEIThermalExpansionConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] DRAGONAPI: Loading NEI Compatibility!
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded Reika.DragonAPI.NEI_APIConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.enderstorage.internal.NEIEnderStorageConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded factorization.nei.NEI_FactorizationInputConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded factorization.nei.NEI_FactorizationRecipeConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded shedar.mods.ic2.nuclearcontrol.crossmod.nei.NEINuclearControlConfig
[20:29:43 INFO]: Client> 113.271: [GC113.271: [ParNew: 303406K->83840K(335552K), 0.0495097 secs] 662970K->444835K(2013312K), 0.0495954 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidBiomass
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidBiofuel
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidSeedOil
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidJuice
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidHoney
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidMead
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidGlass
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidIce
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidMilk
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] Loaded mods.neiplugins.NEIPluginsConfig
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] ROTARYCRAFT: Loading NEI Compatibility!
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] ROTARYCRAFT: Hiding technical blocks from NEI!
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] Loaded Reika.RotaryCraft.ModInterface.NEI.NEI_RotaryConfig
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [ForgeModLoader] InvTweaks: codechicken.enderstorage.storage.item.ContainerEnderItemStorage
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [Minecraft-Client] [CHAT] [Server] Welcome back, ZexMaxwell001
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [Minecraft-Client] [CHAT] WELCOME!
[20:29:44 INFO]: Client> 115.067: [GC115.067: [ParNew: 325053K->73139K(335552K), 0.0645568 secs] 686048K->443775K(2013312K), 0.0646612 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:29:45 INFO]: Client> 2013-12-10 20:29:45 [INFO] [Minecraft-Client] [CHAT] A new version of Biomes O Plenty is available: v1.1.2 for Minecraft 1.6.4
[20:29:28 INFO]: Client> 98.654: [CMS-concurrent-reset: 0.017/0.017 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
[20:29:28 INFO]: Client> 2013-12-10 20:29:28 [INFO] [MapWriter] connection opened to remote server: dusto.homedns.org 25566
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [STDOUT] Setting up custom skins
[20:29:31 INFO]: Client> 101.873: [GC101.873: [ParNew: 224590K->66567K(335552K), 0.0657441 secs] 599639K->441616K(2013312K), 0.0658339 secs] [Times: user=0.22 sys=0.00, real=0.07 secs]
[20:29:31 INFO]: Client> 101.939: [GC [1 CMS-initial-mark: 375049K(1677760K)] 441616K(2013312K), 0.0216408 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
[20:29:31 INFO]: Client> 101.961: [CMS-concurrent-mark-start]
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [ForgeModLoader] [Modstats] Updates found: Modular Force Field System (3.5.0).
[20:29:31 INFO]: Client> 2013-12-10 20:29:31 [INFO] [Minecraft-Client] [CHAT] Updates found: Modular Force Field System (3.5.0).
[20:29:32 INFO]: Client> 102.459: [CMS-concurrent-mark: 0.470/0.499 secs] [Times: user=1.08 sys=0.05, real=0.50 secs]
[20:29:32 INFO]: Client> 102.459: [CMS-concurrent-preclean-start]
[20:29:32 INFO]: Client> 102.465: [CMS-concurrent-preclean: 0.006/0.006 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[20:29:32 INFO]: Client> 102.465: [CMS-concurrent-abortable-preclean-start]
[20:29:37 INFO]: Client> CMS: abort preclean due to time 107.666: [CMS-concurrent-abortable-preclean: 3.294/5.201 secs] [Times: user=3.35 sys=0.00, real=5.20 secs]
[20:29:37 INFO]: Client> 107.666: [GC[YG occupancy: 88248 K (335552 K)]107.666: [Rescan (parallel) , 0.0073352 secs]107.674: [weak refs processing, 0.0000676 secs]107.674: [class unloading, 0.0416197 secs]107.716: [scrub symbol table, 0.0217487 secs]107.737: [scrub string table, 0.0016772 secs] [1 CMS-remark: 375049K(1677760K)] 463297K(2013312K), 0.0871786 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
[20:29:37 INFO]: Client> 107.754: [CMS-concurrent-sweep-start]
[20:29:37 INFO]: Client> 107.914: [CMS-concurrent-sweep: 0.160/0.160 secs] [Times: user=0.19 sys=0.00, real=0.16 secs]
[20:29:37 INFO]: Client> 107.914: [CMS-concurrent-reset-start]
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [GraviGun] [2.0.0] Sending client info to server
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [PortalGun] [2.0.1] Sending client info to server
[20:29:37 INFO]: Client> 107.926: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [MapWriter] onClientLoggedIn: dimension = 0
[20:29:37 INFO]: Client> 2013-12-10 20:29:37 [INFO] [MapWriter] generating block colours
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] generating block map colours from textures
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] created new MwTexture from GL texture id 8 (2048x1024) (2097152 pixels)
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [MapWriter] processed 3199 block textures, 11481 skipped, 348 exceptions
[20:29:38 INFO]: Client> 108.578: [GC108.578: [ParNew: 318279K->51694K(335552K), 0.0400100 secs] 677843K->411258K(2013312K), 0.0400984 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [Minecraft-Client] [CHAT] ZexMaxwell001 joined the game.
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [ForgeModLoader] [THAUMCRAFT] Client received server config settings.
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [ThermalExpansion] Received Server Configs...
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [STDOUT] Setting up custom skins
[20:29:38 INFO]: Client> 2013-12-10 20:29:38 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.multipart.nei.NEI_MicroblockConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] IC2 NEI Submodule initialized
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded ic2.neiIntegration.core.NEIIC2Config
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.wirelessredstone.addons.NEIWirelessAddonConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded thermalexpansion.plugins.nei.NEIThermalExpansionConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] DRAGONAPI: Loading NEI Compatibility!
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded Reika.DragonAPI.NEI_APIConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded codechicken.enderstorage.internal.NEIEnderStorageConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded factorization.nei.NEI_FactorizationInputConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded factorization.nei.NEI_FactorizationRecipeConfig
[20:29:42 INFO]: Client> 2013-12-10 20:29:42 [INFO] [STDOUT] Loaded shedar.mods.ic2.nuclearcontrol.crossmod.nei.NEINuclearControlConfig
[20:29:43 INFO]: Client> 113.271: [GC113.271: [ParNew: 303406K->83840K(335552K), 0.0495097 secs] 662970K->444835K(2013312K), 0.0495954 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidBiomass
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidBiofuel
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidSeedOil
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidJuice
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidHoney
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidMead
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidGlass
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidIce
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [WARNING] [ForgeModLoader] Could not retrieve Forestry item identified by: liquidMilk
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] Loaded mods.neiplugins.NEIPluginsConfig
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] ROTARYCRAFT: Loading NEI Compatibility!
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] ROTARYCRAFT: Hiding technical blocks from NEI!
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [STDOUT] Loaded Reika.RotaryCraft.ModInterface.NEI.NEI_RotaryConfig
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [ForgeModLoader] InvTweaks: codechicken.enderstorage.storage.item.ContainerEnderItemStorage
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [Minecraft-Client] [CHAT] [Server] Welcome back, ZexMaxwell001
[20:29:43 INFO]: Client> 2013-12-10 20:29:43 [INFO] [Minecraft-Client] [CHAT] WELCOME!
[20:29:44 INFO]: Client> 115.067: [GC115.067: [ParNew: 325053K->73139K(335552K), 0.0645568 secs] 686048K->443775K(2013312K), 0.0646612 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:29:45 INFO]: Client> 2013-12-10 20:29:45 [INFO] [Minecraft-Client] [CHAT] A new version of Biomes O Plenty is available: v1.1.2 for Minecraft 1.6.4
From :28 to :45, 17 seconds of initialization ...
[20:29:45 INFO]: Client> 115.950: [GC115.950: [ParNew: 316428K->74646K(335552K), 0.0598469 secs] 687065K->453539K(2013312K), 0.0599360 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
[20:29:47 INFO]: Client> 118.039: [GC118.039: [ParNew: 326358K->68520K(335552K), 0.0696180 secs] 705251K->456039K(2013312K), 0.0697079 secs] [Times: user=0.25 sys=0.00, real=0.07 secs]
[20:29:55 INFO]: Client> 125.534: [GC125.534: [ParNew: 312066K->67140K(335552K), 0.0526373 secs] 699586K->459076K(2013312K), 0.0527206 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
[20:30:02 INFO]: Client> 132.761: [GC132.761: [ParNew: 318852K->65542K(335552K), 0.0499674 secs] 710788K->458613K(2013312K), 0.0500458 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:29:47 INFO]: Client> 118.039: [GC118.039: [ParNew: 326358K->68520K(335552K), 0.0696180 secs] 705251K->456039K(2013312K), 0.0697079 secs] [Times: user=0.25 sys=0.00, real=0.07 secs]
[20:29:55 INFO]: Client> 125.534: [GC125.534: [ParNew: 312066K->67140K(335552K), 0.0526373 secs] 699586K->459076K(2013312K), 0.0527206 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
[20:30:02 INFO]: Client> 132.761: [GC132.761: [ParNew: 318852K->65542K(335552K), 0.0499674 secs] 710788K->458613K(2013312K), 0.0500458 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
From :45 to :03, 18 seconds of ... ???? What the heck is happening here? Clueless
Then, more initialization ...
[20:30:03 INFO]: Client> 2013-12-10 20:30:03 [INFO] [GraviGun] [2.0.0] Received world props from server.
[20:30:03 INFO]: Client> 2013-12-10 20:30:03 [INFO] [PortalGun] [2.0.1] Received world props from server.
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] Inserted super call into axm.c
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] computercraft: Searching for RedPowerWorld...
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] computercraft: RedPowerWorld not found.
[20:30:05 INFO]: Client> 135.994: [GC135.994: [ParNew: 317254K->78610K(335552K), 0.0699348 secs] 710325K->478566K(2013312K), 0.0700251 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:30:08 INFO]: Client> 138.425: [GC138.425: [ParNew: 330322K->80724K(335552K), 0.0618847 secs] 730278K->481422K(2013312K), 0.0622287 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
[20:30:10 INFO]: Client> 2013-12-10 20:30:10 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:30:11 INFO]: Client> 141.427: [GC141.427: [ParNew: 332436K->50975K(335552K), 0.0645983 secs] 733134K->456076K(2013312K), 0.0646850 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
[20:30:11 INFO]: Client> 141.496: [GC141.496: [ParNew: 52799K->35620K(335552K), 0.0519046 secs] 457901K->451716K(2013312K), 0.0519983 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/grindertex.png
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Empty or invalid rednet blacklist entry found. Not adding to rednet blacklist.
[20:30:12 INFO]: Client> 143.074: [GC143.074: [ParNew: 274100K->34279K(335552K), 0.0425758 secs] 690195K->457172K(2013312K), 0.0426653 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to Textures/Items/items2.png
[20:30:13 INFO]: Client> 2013-12-10 20:30:13 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/actex.png
[20:30:13 INFO]: Client> 2013-12-10 20:30:13 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/dc.png
[20:30:03 INFO]: Client> 2013-12-10 20:30:03 [INFO] [PortalGun] [2.0.1] Received world props from server.
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] Inserted super call into axm.c
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] computercraft: Searching for RedPowerWorld...
[20:30:04 INFO]: Client> 2013-12-10 20:30:04 [INFO] [STDOUT] computercraft: RedPowerWorld not found.
[20:30:05 INFO]: Client> 135.994: [GC135.994: [ParNew: 317254K->78610K(335552K), 0.0699348 secs] 710325K->478566K(2013312K), 0.0700251 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:30:08 INFO]: Client> 138.425: [GC138.425: [ParNew: 330322K->80724K(335552K), 0.0618847 secs] 730278K->481422K(2013312K), 0.0622287 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
[20:30:10 INFO]: Client> 2013-12-10 20:30:10 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:30:11 INFO]: Client> 141.427: [GC141.427: [ParNew: 332436K->50975K(335552K), 0.0645983 secs] 733134K->456076K(2013312K), 0.0646850 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
[20:30:11 INFO]: Client> 141.496: [GC141.496: [ParNew: 52799K->35620K(335552K), 0.0519046 secs] 457901K->451716K(2013312K), 0.0519983 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/grindertex.png
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Empty or invalid rednet blacklist entry found. Not adding to rednet blacklist.
[20:30:12 INFO]: Client> 143.074: [GC143.074: [ParNew: 274100K->34279K(335552K), 0.0425758 secs] 690195K->457172K(2013312K), 0.0426653 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
[20:30:12 INFO]: Client> 2013-12-10 20:30:12 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to Textures/Items/items2.png
[20:30:13 INFO]: Client> 2013-12-10 20:30:13 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/actex.png
[20:30:13 INFO]: Client> 2013-12-10 20:30:13 [INFO] [STDOUT] Pipelining texture from Reika.RotaryCraft.RotaryCraft to /Reika/RotaryCraft/Textures/TileEntityTex/dc.png
Ok, that seems to be the last of the initialization messages.
[20:30:14 INFO]: Client> 145.196: [GC145.196: [ParNew: 275714K->41101K(335552K), 0.0439535 secs] 698607K->465207K(2013312K), 0.0440249 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
[20:30:22 INFO]: Client> 152.949: [GC152.949: [ParNew: 292813K->43465K(335552K), 0.0454871 secs] 716919K->468520K(2013312K), 0.0455732 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
[20:30:37 INFO]: Client> 168.082: [GC168.082: [ParNew: 294225K->61822K(335552K), 0.0494187 secs] 719280K->487275K(2013312K), 0.0494967 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:30:50 INFO]: Client> 181.121: [GC181.121: [ParNew: 313534K->83840K(335552K), 0.0709885 secs] 738987K->514743K(2013312K), 0.0710814 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:30:57 INFO]: Client> 2013-12-10 20:30:57 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:30:59 INFO]: Client> 189.813: [GC189.813: [ParNew: 335499K->44552K(335552K), 0.0552860 secs] 766402K->477856K(2013312K), 0.0553647 secs] [Times: user=0.17 sys=0.00, real=0.06 secs]
[20:31:22 INFO]: Client> 212.495: [GC212.495: [ParNew: 295956K->64637K(335552K), 0.0527517 secs] 729260K->503012K(2013312K), 0.0528438 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:31:41 INFO]: Client> 232.028: [GC232.028: [ParNew: 316349K->82405K(335552K), 0.0561131 secs] 754724K->520782K(2013312K), 0.0561910 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [Minecraft-Client] Stopping!
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [STDOUT]
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [STDOUT] SoundSystem shutting down...
[20:30:22 INFO]: Client> 152.949: [GC152.949: [ParNew: 292813K->43465K(335552K), 0.0454871 secs] 716919K->468520K(2013312K), 0.0455732 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
[20:30:37 INFO]: Client> 168.082: [GC168.082: [ParNew: 294225K->61822K(335552K), 0.0494187 secs] 719280K->487275K(2013312K), 0.0494967 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:30:50 INFO]: Client> 181.121: [GC181.121: [ParNew: 313534K->83840K(335552K), 0.0709885 secs] 738987K->514743K(2013312K), 0.0710814 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
[20:30:57 INFO]: Client> 2013-12-10 20:30:57 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:30:59 INFO]: Client> 189.813: [GC189.813: [ParNew: 335499K->44552K(335552K), 0.0552860 secs] 766402K->477856K(2013312K), 0.0553647 secs] [Times: user=0.17 sys=0.00, real=0.06 secs]
[20:31:22 INFO]: Client> 212.495: [GC212.495: [ParNew: 295956K->64637K(335552K), 0.0527517 secs] 729260K->503012K(2013312K), 0.0528438 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
[20:31:41 INFO]: Client> 232.028: [GC232.028: [ParNew: 316349K->82405K(335552K), 0.0561131 secs] 754724K->520782K(2013312K), 0.0561910 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:43 INFO]: Client> 2013-12-10 20:31:43 [INFO] [STDOUT] Loading World: remote/75.129.55.236~25566/world
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [Minecraft-Client] Stopping!
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [STDOUT]
[20:31:48 INFO]: Client> 2013-12-10 20:31:48 [INFO] [STDOUT] SoundSystem shutting down...
And now it shuts down.
So, at least for the question, why is it taking so long to log in, the answer is, your mods are still getting ready. A better question is, since the general idea of "Lets get data from the server, and set up / initialize to that" makes sense, why does forge not have a recognition of this, with players in a "in-the-process-of-logging-on", but not yet actually logged on, state -- unable to interact or do anything on the server, until the client reports "I'm now fully initialized" to the
server?
During this time period (login), are you in the same situation of "able to move around, but not able to interact"?
---
Now, nothing in here is explaining the delay on mystcraft portals. By the time you get to using those, initialization of mods has finished.
Does it only happen on mystcraft portals?
What about mystcraft books?
What about nether portals?
Do you have any other dimension travel mods -- deep dark, promised land -- and do they also behave the same?[DOUBLEPOST=1386732555][/DOUBLEPOST]Ok, let me check your edit with the server logs ...
During this time period (login), are you in the same situation of "able to move around, but not able to interact"?
yes.
Does it only happen on mystcraft portals?
mystcraft portals and books. the server log that I ninja-ed in will show you it.
What about nether portals?
yes. what is funny, I'll be in creative mode, walk through the nether portal, pop out instantly on the other side, move around (mobs are not moving) then zip back into the "loading world" screen. it takes so long to load, it pops me back out into the over world.
Do you have any other dimension travel mods -- deep dark, promised land -- and do they also behave the same?
I do have deep dark, promised land as well. never tested it because no one in my server got to that point.
yes.
Does it only happen on mystcraft portals?
mystcraft portals and books. the server log that I ninja-ed in will show you it.
What about nether portals?
yes. what is funny, I'll be in creative mode, walk through the nether portal, pop out instantly on the other side, move around (mobs are not moving) then zip back into the "loading world" screen. it takes so long to load, it pops me back out into the over world.
Do you have any other dimension travel mods -- deep dark, promised land -- and do they also behave the same?
I do have deep dark, promised land as well. never tested it because no one in my server got to that point.
So looking at the console log info:
:15 to :34, 19 seconds and it seems to be client-side getting ready, like we saw last time
:53, and it still seems to be doing login processing on the server
Ok, 45 seconds after starting to get on, you are now on and using a book.
Console : 2013-12-10 20:55:29 [INFO] <ZexMaxwell001> bookhop
What is very clear here: Garbage collection is not doing anything to slow you down on either side. The times for the collections are tiny, and the CMS collections are completing in the background.
There is a huge delay getting on, and there is something causing a delay doing a dimension hop, but there is nothing in the server logs to show what it is.
Now, looking at your next reply:
The client has received information from the server, and thinks it can do things. So you are walking around -- that's all client side -- and the client is trying to send data to the server as you try to interact, but the server isn't paying attention to any of it.
The client and server have gotten completely de-synched. That's bad -- that should never happen. I have no clue how to begin to debug that one.
And that's the same thing. The client has data, and is trying to use it, but the server is in a completely different state.
Whatever is happening, it seems to not be related to garbage collection, nor to mystcraft (it happens in the nether, and if it happens in the deep dark, then it's definitely something else.)
Console : 2013-12-10 20:54:13 [INFO] ZexMaxwell001[/75.121.155.245:18697] logged in with entity id 1426 at ([world] -1869.5362731553614, 73.0, 1470.5339756943285)
Console : 2013-12-10 20:54:14 [INFO] Loading Player: ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] Sending serverside check to: ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] [Server] Welcome back, ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] [CONSOLE->ZexMaxwell001] WELCOME!
Console : 222.085: [GC222.085: [ParNew: 324904K->67878K(335552K), 0.0732902 secs] 1049657K->792631K(2013312K), 0.0733933 secs] [Times: user=0.30 sys=0.00, real=0.07 secs]
Console : 224.332: [GC224.332: [ParNew: 319590K->83840K(335552K), 0.0645324 secs] 1044343K->808596K(2013312K), 0.0646450 secs] [Times: user=0.25 sys=0.00, real=0.06 secs]
Console : 226.952: [GC226.952: [ParNew: 335552K->82877K(335552K), 0.0709034 secs] 1060308K->823779K(2013312K), 0.0709899 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
Console : 2013-12-10 20:54:20 [INFO] [2.0.0] Recieved client info from ZexMaxwell001
Console : 2013-12-10 20:54:20 [INFO] [2.0.1] Recieved client info from ZexMaxwell001
Console : 229.724: [GC229.724: [ParNew: 334589K->69138K(335552K), 0.0460928 secs] 1075491K->810040K(2013312K), 0.0461930 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 232.440: [GC232.440: [ParNew: 320850K->83840K(335552K), 0.0477742 secs] 1061752K->825074K(2013312K), 0.0478636 secs] [Times: user=0.17 sys=0.00, real=0.05 secs]
Console : 235.167: [GC235.167: [ParNew: 335552K->68313K(335552K), 0.0453652 secs] 1076786K->810116K(2013312K), 0.0454580 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 237.879: [GC237.879: [ParNew: 320025K->83840K(335552K), 0.0427348 secs] 1061828K->825705K(2013312K), 0.0428205 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 240.586: [GC240.586: [ParNew: 335552K->65377K(335552K), 0.0409615 secs] 1077417K->807823K(2013312K), 0.0410441 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 2013-12-10 20:54:34 [INFO] <ZexMaxwell001> joined
Console : 2013-12-10 20:54:14 [INFO] Loading Player: ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] Sending serverside check to: ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] [Server] Welcome back, ZexMaxwell001
Console : 2013-12-10 20:54:14 [INFO] [CONSOLE->ZexMaxwell001] WELCOME!
Console : 222.085: [GC222.085: [ParNew: 324904K->67878K(335552K), 0.0732902 secs] 1049657K->792631K(2013312K), 0.0733933 secs] [Times: user=0.30 sys=0.00, real=0.07 secs]
Console : 224.332: [GC224.332: [ParNew: 319590K->83840K(335552K), 0.0645324 secs] 1044343K->808596K(2013312K), 0.0646450 secs] [Times: user=0.25 sys=0.00, real=0.06 secs]
Console : 226.952: [GC226.952: [ParNew: 335552K->82877K(335552K), 0.0709034 secs] 1060308K->823779K(2013312K), 0.0709899 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
Console : 2013-12-10 20:54:20 [INFO] [2.0.0] Recieved client info from ZexMaxwell001
Console : 2013-12-10 20:54:20 [INFO] [2.0.1] Recieved client info from ZexMaxwell001
Console : 229.724: [GC229.724: [ParNew: 334589K->69138K(335552K), 0.0460928 secs] 1075491K->810040K(2013312K), 0.0461930 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 232.440: [GC232.440: [ParNew: 320850K->83840K(335552K), 0.0477742 secs] 1061752K->825074K(2013312K), 0.0478636 secs] [Times: user=0.17 sys=0.00, real=0.05 secs]
Console : 235.167: [GC235.167: [ParNew: 335552K->68313K(335552K), 0.0453652 secs] 1076786K->810116K(2013312K), 0.0454580 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 237.879: [GC237.879: [ParNew: 320025K->83840K(335552K), 0.0427348 secs] 1061828K->825705K(2013312K), 0.0428205 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 240.586: [GC240.586: [ParNew: 335552K->65377K(335552K), 0.0409615 secs] 1077417K->807823K(2013312K), 0.0410441 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 2013-12-10 20:54:34 [INFO] <ZexMaxwell001> joined
:15 to :34, 19 seconds and it seems to be client-side getting ready, like we saw last time
Console : 243.193: [GC243.193: [ParNew: 317089K->45769K(335552K), 0.0658585 secs] 1059535K->817602K(2013312K), 0.0659411 secs] [Times: user=0.17 sys=0.01, real=0.07 secs]
Console : 245.927: [GC245.927: [ParNew: 297481K->18610K(335552K), 0.0241779 secs] 1069314K->794684K(2013312K), 0.0242687 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]
Console : 248.540: [GC248.540: [ParNew: 270322K->15306K(335552K), 0.0219110 secs] 1046396K->796165K(2013312K), 0.0220073 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 251.217: [GC251.217: [ParNew: 267018K->18031K(335552K), 0.0205961 secs] 1047877K->799013K(2013312K), 0.0206817 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 253.900: [GC253.900: [ParNew: 269743K->22761K(335552K), 0.0211418 secs] 1050725K->803811K(2013312K), 0.0212356 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:54:49 [WARNING] Trying to propagate invalid map data 0
Console : 256.575: [GC256.575: [ParNew: 274473K->27276K(335552K), 0.0241013 secs] 1055523K->808337K(2013312K), 0.0241921 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 259.288: [GC259.288: [ParNew: 278988K->30211K(335552K), 0.0229918 secs] 1060049K->811305K(2013312K), 0.0230852 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:54:53 [INFO] Sending serverside check to: ZexMaxwell001
Console : 245.927: [GC245.927: [ParNew: 297481K->18610K(335552K), 0.0241779 secs] 1069314K->794684K(2013312K), 0.0242687 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]
Console : 248.540: [GC248.540: [ParNew: 270322K->15306K(335552K), 0.0219110 secs] 1046396K->796165K(2013312K), 0.0220073 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 251.217: [GC251.217: [ParNew: 267018K->18031K(335552K), 0.0205961 secs] 1047877K->799013K(2013312K), 0.0206817 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 253.900: [GC253.900: [ParNew: 269743K->22761K(335552K), 0.0211418 secs] 1050725K->803811K(2013312K), 0.0212356 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:54:49 [WARNING] Trying to propagate invalid map data 0
Console : 256.575: [GC256.575: [ParNew: 274473K->27276K(335552K), 0.0241013 secs] 1055523K->808337K(2013312K), 0.0241921 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 259.288: [GC259.288: [ParNew: 278988K->30211K(335552K), 0.0229918 secs] 1060049K->811305K(2013312K), 0.0230852 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:54:53 [INFO] Sending serverside check to: ZexMaxwell001
:53, and it still seems to be doing login processing on the server
Console : 261.639: [GC261.639: [ParNew: 281923K->76112K(335552K), 0.0571218 secs] 1063017K->857222K(2013312K), 0.0572164 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
Console : 263.417: [GC263.417: [ParNew: 327824K->83840K(335552K), 0.0565405 secs] 1108934K->865183K(2013312K), 0.0566235 secs] [Times: user=0.20 sys=0.00, real=0.06 secs]
Console : 265.862: [GC265.862: [ParNew: 335552K->83840K(335552K), 0.0565349 secs] 1116895K->880313K(2013312K), 0.0566295 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
Console : 2013-12-10 20:55:01 [INFO] <ZexMaxwell001> book hop
Console : 263.417: [GC263.417: [ParNew: 327824K->83840K(335552K), 0.0565405 secs] 1108934K->865183K(2013312K), 0.0566235 secs] [Times: user=0.20 sys=0.00, real=0.06 secs]
Console : 265.862: [GC265.862: [ParNew: 335552K->83840K(335552K), 0.0565349 secs] 1116895K->880313K(2013312K), 0.0566295 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
Console : 2013-12-10 20:55:01 [INFO] <ZexMaxwell001> book hop
Ok, 45 seconds after starting to get on, you are now on and using a book.
Console : 268.523: [GC268.523: [ParNew: 335552K->83840K(335552K), 0.0505809 secs] 1132025K->883316K(2013312K), 0.0506639 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
Console : 271.239: [GC271.239: [ParNew: 335552K->81429K(335552K), 0.0493930 secs] 1135028K->880906K(2013312K), 0.0494804 secs] [Times: user=0.23 sys=0.00, real=0.05 secs]
Console : 273.906: [GC273.906: [ParNew: 333141K->83840K(335552K), 0.0538194 secs] 1132618K->883317K(2013312K), 0.0539234 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 276.604: [GC276.604: [ParNew: 335552K->63326K(335552K), 0.0467529 secs] 1135029K->862803K(2013312K), 0.0468458 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 279.316: [GC279.316: [ParNew: 315038K->76728K(335552K), 0.0419614 secs] 1114515K->876286K(2013312K), 0.0420521 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 281.973: [GC281.973: [ParNew: 328440K->39926K(335552K), 0.0747425 secs] 1127998K->871788K(2013312K), 0.0748440 secs] [Times: user=0.22 sys=0.00, real=0.08 secs]
Console : 284.675: [GC284.675: [ParNew: 291638K->39681K(335552K), 0.0287978 secs] 1123500K->871793K(2013312K), 0.0288817 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
Console : 287.326: [GC287.326: [ParNew: 291393K->34214K(335552K), 0.0328946 secs] 1123505K->876914K(2013312K), 0.0329956 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 287.360: [GC [1 CMS-initial-mark: 842700K(1677760K)] 881856K(2013312K), 0.0162583 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
Console : 287.376: [CMS-concurrent-mark-start]
Console : 288.132: [CMS-concurrent-mark: 0.755/0.755 secs] [Times: user=0.97 sys=0.00, real=0.76 secs]
Console : 288.132: [CMS-concurrent-preclean-start]
Console : 288.140: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
Console : 288.140: [CMS-concurrent-abortable-preclean-start]
Console : 290.008: [GC290.008: [ParNew: 285926K->42912K(335552K), 0.0255789 secs] 1128626K->885765K(2013312K), 0.0256603 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
Console : 2013-12-10 20:55:24 [INFO] Sending serverside check to: ZexMaxwell001
Console : 291.522: [CMS-concurrent-abortable-preclean: 1.538/3.382 secs] [Times: user=3.54 sys=0.16, real=3.38 secs]
Console : 291.525: [GC[YG occupancy: 209260 K (335552 K)]291.525: [Rescan (parallel) , 0.0345622 secs]291.560: [weak refs processing, 0.0000796 secs]291.560: [class unloading, 0.1338067 secs]291.694: [scrub symbol table, 0.0194507 secs]291.713: [scrub string table, 0.0017156 secs] [1 CMS-remark: 842853K(1677760K)] 1052113K(2013312K), 0.4719684 secs] [Times: user=0.56 sys=0.00, real=0.47 secs]
Console : 291.998: [CMS-concurrent-sweep-start]
Console : 292.393: [CMS-concurrent-sweep: 0.394/0.395 secs] [Times: user=1.34 sys=0.08, real=0.39 secs]
Console : 292.393: [CMS-concurrent-reset-start]
Console : 292.417: [CMS-concurrent-reset: 0.025/0.025 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
Console : 292.433: [GC292.433: [ParNew: 294624K->61186K(335552K), 0.0473688 secs] 876609K->643191K(2013312K), 0.0474600 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 293.969: [GC293.969: [ParNew: 312898K->83840K(335552K), 0.0491615 secs] 894903K->665872K(2013312K), 0.0492526 secs] [Times: user=0.25 sys=0.00, real=0.05 secs]
Console : 296.393: [GC296.393: [ParNew: 335552K->83840K(335552K), 0.0535386 secs] 917584K->673583K(2013312K), 0.0536294 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]'
Console : 271.239: [GC271.239: [ParNew: 335552K->81429K(335552K), 0.0493930 secs] 1135028K->880906K(2013312K), 0.0494804 secs] [Times: user=0.23 sys=0.00, real=0.05 secs]
Console : 273.906: [GC273.906: [ParNew: 333141K->83840K(335552K), 0.0538194 secs] 1132618K->883317K(2013312K), 0.0539234 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 276.604: [GC276.604: [ParNew: 335552K->63326K(335552K), 0.0467529 secs] 1135029K->862803K(2013312K), 0.0468458 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 279.316: [GC279.316: [ParNew: 315038K->76728K(335552K), 0.0419614 secs] 1114515K->876286K(2013312K), 0.0420521 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 281.973: [GC281.973: [ParNew: 328440K->39926K(335552K), 0.0747425 secs] 1127998K->871788K(2013312K), 0.0748440 secs] [Times: user=0.22 sys=0.00, real=0.08 secs]
Console : 284.675: [GC284.675: [ParNew: 291638K->39681K(335552K), 0.0287978 secs] 1123500K->871793K(2013312K), 0.0288817 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
Console : 287.326: [GC287.326: [ParNew: 291393K->34214K(335552K), 0.0328946 secs] 1123505K->876914K(2013312K), 0.0329956 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 287.360: [GC [1 CMS-initial-mark: 842700K(1677760K)] 881856K(2013312K), 0.0162583 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
Console : 287.376: [CMS-concurrent-mark-start]
Console : 288.132: [CMS-concurrent-mark: 0.755/0.755 secs] [Times: user=0.97 sys=0.00, real=0.76 secs]
Console : 288.132: [CMS-concurrent-preclean-start]
Console : 288.140: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
Console : 288.140: [CMS-concurrent-abortable-preclean-start]
Console : 290.008: [GC290.008: [ParNew: 285926K->42912K(335552K), 0.0255789 secs] 1128626K->885765K(2013312K), 0.0256603 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
Console : 2013-12-10 20:55:24 [INFO] Sending serverside check to: ZexMaxwell001
Console : 291.522: [CMS-concurrent-abortable-preclean: 1.538/3.382 secs] [Times: user=3.54 sys=0.16, real=3.38 secs]
Console : 291.525: [GC[YG occupancy: 209260 K (335552 K)]291.525: [Rescan (parallel) , 0.0345622 secs]291.560: [weak refs processing, 0.0000796 secs]291.560: [class unloading, 0.1338067 secs]291.694: [scrub symbol table, 0.0194507 secs]291.713: [scrub string table, 0.0017156 secs] [1 CMS-remark: 842853K(1677760K)] 1052113K(2013312K), 0.4719684 secs] [Times: user=0.56 sys=0.00, real=0.47 secs]
Console : 291.998: [CMS-concurrent-sweep-start]
Console : 292.393: [CMS-concurrent-sweep: 0.394/0.395 secs] [Times: user=1.34 sys=0.08, real=0.39 secs]
Console : 292.393: [CMS-concurrent-reset-start]
Console : 292.417: [CMS-concurrent-reset: 0.025/0.025 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
Console : 292.433: [GC292.433: [ParNew: 294624K->61186K(335552K), 0.0473688 secs] 876609K->643191K(2013312K), 0.0474600 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 293.969: [GC293.969: [ParNew: 312898K->83840K(335552K), 0.0491615 secs] 894903K->665872K(2013312K), 0.0492526 secs] [Times: user=0.25 sys=0.00, real=0.05 secs]
Console : 296.393: [GC296.393: [ParNew: 335552K->83840K(335552K), 0.0535386 secs] 917584K->673583K(2013312K), 0.0536294 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]'
Console : 2013-12-10 20:55:29 [INFO] <ZexMaxwell001> bookhop
Console : 299.053: [GC299.054: [ParNew: 335552K->70217K(335552K), 0.0771160 secs] 925295K->695792K(2013312K), 0.0772033 secs] [Times: user=0.22 sys=0.05, real=0.08 secs]
Console : 2013-12-10 20:55:33 [INFO] Sending serverside check to: ZexMaxwell001
Console : 2013-12-10 20:55:33 [INFO] Sending serverside check to: ZexMaxwell001
Console : 301.613: [GC301.613: [ParNew: 321929K->47795K(335552K), 0.0295854 secs] 947504K->673370K(2013312K), 0.0296787 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 304.319: [GC304.319: [ParNew: 299507K->36828K(335552K), 0.0298718 secs] 925082K->662403K(2013312K), 0.0299942 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 307.020: [GC307.020: [ParNew: 288540K->32209K(335552K), 0.0271824 secs] 914115K->657784K(2013312K), 0.0272761 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
Console : 309.672: [GC309.672: [ParNew: 283921K->43622K(335552K), 0.0245499 secs] 909496K->669197K(2013312K), 0.0246522 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
Console : 312.424: [GC312.424: [ParNew: 295334K->24524K(335552K), 0.0245927 secs] 920909K->650099K(2013312K), 0.0247096 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:55:45 [INFO] <ZexMaxwell001> portal hop
Console : 315.125: [GC315.125: [ParNew: 276236K->30479K(335552K), 0.0236330 secs] 901811K->656480K(2013312K), 0.0237379 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 317.694: [GC317.694: [ParNew: 282191K->20044K(335552K), 0.0236215 secs] 908192K->650199K(2013312K), 0.0237272 secs] [Times: user=0.12 sys=0.00, real=0.02 secs]
Console : 320.277: [GC320.277: [ParNew: 271756K->17605K(335552K), 0.0198423 secs] 901911K->647842K(2013312K), 0.0199429 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 322.879: [GC322.879: [ParNew: 269317K->24899K(335552K), 0.0213263 secs] 899554K->655872K(2013312K), 0.0214214 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 324.683: [GC324.683: [ParNew: 276611K->56369K(335552K), 0.0412063 secs] 907584K->687383K(2013312K), 0.0413022 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 327.217: [GC327.217: [ParNew: 308081K->76712K(335552K), 0.0464528 secs] 939095K->707765K(2013312K), 0.0465573 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 329.925: [GC329.925: [ParNew: 328424K->82730K(335552K), 0.0446769 secs] 959477K->713819K(2013312K), 0.0447766 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 2013-12-10 20:56:03 [INFO] <ZexMaxwell001> ending
Console : 332.589: [GC332.589: [ParNew: 334442K->83840K(335552K), 0.0455193 secs] 965531K->714955K(2013312K), 0.0456117 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 335.299: [GC335.299: [ParNew: 335552K->83840K(335552K), 0.0441440 secs] 966667K->714957K(2013312K), 0.0442330 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 337.915: [GC337.915: [ParNew: 335552K->65588K(335552K), 0.0369071 secs] 969366K->700461K(2013312K), 0.0370025 secs] [Times: user=0.14 sys=0.00, real=0.04 secs]
Console : 337.952: [GC337.953: [ParNew: 70503K->54818K(335552K), 0.0385328 secs] 705377K->694833K(2013312K), 0.0386278 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
Console : 340.617: [GC340.617: [ParNew: 306530K->58612K(335552K), 0.0390032 secs] 946545K->703082K(2013312K), 0.0391021 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
Console : 343.272: [GC343.272: [ParNew: 310324K->25308K(335552K), 0.0513792 secs] 954794K->696442K(2013312K), 0.0514656 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 345.993: [GC345.993: [ParNew: 277020K->10763K(335552K), 0.0178913 secs] 948154K->682566K(2013312K), 0.0179923 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:56:19 [INFO] ZexMaxwell001 lost connection: disconnect.quitting
Console : 2013-12-10 20:56:19 [INFO] Connection reset
Console : 2013-12-10 20:56:19 [INFO] Unloading Player: ZexMaxwell001
Console : 2013-12-10 20:56:19 [INFO] eZexMaxwell001 left the game.
Console : 372.523: [GC372.523: [ParNew: 262475K->8486K(335552K), 0.0183698 secs] 934278K->680378K(2013312K), 0.0184636 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:57:06 [INFO] CONSOLE: Stopping the server..
Console : 2013-12-10 20:55:33 [INFO] Sending serverside check to: ZexMaxwell001
Console : 2013-12-10 20:55:33 [INFO] Sending serverside check to: ZexMaxwell001
Console : 301.613: [GC301.613: [ParNew: 321929K->47795K(335552K), 0.0295854 secs] 947504K->673370K(2013312K), 0.0296787 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 304.319: [GC304.319: [ParNew: 299507K->36828K(335552K), 0.0298718 secs] 925082K->662403K(2013312K), 0.0299942 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
Console : 307.020: [GC307.020: [ParNew: 288540K->32209K(335552K), 0.0271824 secs] 914115K->657784K(2013312K), 0.0272761 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
Console : 309.672: [GC309.672: [ParNew: 283921K->43622K(335552K), 0.0245499 secs] 909496K->669197K(2013312K), 0.0246522 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
Console : 312.424: [GC312.424: [ParNew: 295334K->24524K(335552K), 0.0245927 secs] 920909K->650099K(2013312K), 0.0247096 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:55:45 [INFO] <ZexMaxwell001> portal hop
Console : 315.125: [GC315.125: [ParNew: 276236K->30479K(335552K), 0.0236330 secs] 901811K->656480K(2013312K), 0.0237379 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 317.694: [GC317.694: [ParNew: 282191K->20044K(335552K), 0.0236215 secs] 908192K->650199K(2013312K), 0.0237272 secs] [Times: user=0.12 sys=0.00, real=0.02 secs]
Console : 320.277: [GC320.277: [ParNew: 271756K->17605K(335552K), 0.0198423 secs] 901911K->647842K(2013312K), 0.0199429 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 322.879: [GC322.879: [ParNew: 269317K->24899K(335552K), 0.0213263 secs] 899554K->655872K(2013312K), 0.0214214 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 324.683: [GC324.683: [ParNew: 276611K->56369K(335552K), 0.0412063 secs] 907584K->687383K(2013312K), 0.0413022 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 327.217: [GC327.217: [ParNew: 308081K->76712K(335552K), 0.0464528 secs] 939095K->707765K(2013312K), 0.0465573 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 329.925: [GC329.925: [ParNew: 328424K->82730K(335552K), 0.0446769 secs] 959477K->713819K(2013312K), 0.0447766 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 2013-12-10 20:56:03 [INFO] <ZexMaxwell001> ending
Console : 332.589: [GC332.589: [ParNew: 334442K->83840K(335552K), 0.0455193 secs] 965531K->714955K(2013312K), 0.0456117 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 335.299: [GC335.299: [ParNew: 335552K->83840K(335552K), 0.0441440 secs] 966667K->714957K(2013312K), 0.0442330 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
Console : 337.915: [GC337.915: [ParNew: 335552K->65588K(335552K), 0.0369071 secs] 969366K->700461K(2013312K), 0.0370025 secs] [Times: user=0.14 sys=0.00, real=0.04 secs]
Console : 337.952: [GC337.953: [ParNew: 70503K->54818K(335552K), 0.0385328 secs] 705377K->694833K(2013312K), 0.0386278 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
Console : 340.617: [GC340.617: [ParNew: 306530K->58612K(335552K), 0.0390032 secs] 946545K->703082K(2013312K), 0.0391021 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
Console : 343.272: [GC343.272: [ParNew: 310324K->25308K(335552K), 0.0513792 secs] 954794K->696442K(2013312K), 0.0514656 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Console : 345.993: [GC345.993: [ParNew: 277020K->10763K(335552K), 0.0178913 secs] 948154K->682566K(2013312K), 0.0179923 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:56:19 [INFO] ZexMaxwell001 lost connection: disconnect.quitting
Console : 2013-12-10 20:56:19 [INFO] Connection reset
Console : 2013-12-10 20:56:19 [INFO] Unloading Player: ZexMaxwell001
Console : 2013-12-10 20:56:19 [INFO] eZexMaxwell001 left the game.
Console : 372.523: [GC372.523: [ParNew: 262475K->8486K(335552K), 0.0183698 secs] 934278K->680378K(2013312K), 0.0184636 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
Console : 2013-12-10 20:57:06 [INFO] CONSOLE: Stopping the server..
What is very clear here: Garbage collection is not doing anything to slow you down on either side. The times for the collections are tiny, and the CMS collections are completing in the background.
There is a huge delay getting on, and there is something causing a delay doing a dimension hop, but there is nothing in the server logs to show what it is.
Now, looking at your next reply:
This is odd.
The client has received information from the server, and thinks it can do things. So you are walking around -- that's all client side -- and the client is trying to send data to the server as you try to interact, but the server isn't paying attention to any of it.
The client and server have gotten completely de-synched. That's bad -- that should never happen. I have no clue how to begin to debug that one.
And that's the same thing. The client has data, and is trying to use it, but the server is in a completely different state.
It would be interesting to use creative mode to summon in a deep dark portal block, head over there, and see if you can break a block in the wall. I suspect it will also fail.
Whatever is happening, it seems to not be related to garbage collection, nor to mystcraft (it happens in the nether, and if it happens in the deep dark, then it's definitely something else.)
Is this good for a 2gb server ?
Server specs
E3-1240v2 with 2GB RAM
From http://pytohost.com/
Thanks
Server specs
E3-1240v2 with 2GB RAM
From http://pytohost.com/
Thanks
So, at least on my machine, the parms for the launcher do not work. I set the max ram slider to 2048 and copy/pasted the listed parms into the additional java parms box. Here's the result:
Setting MinMemory to 256
Setting MaxMemory to 2048
Error occurred during initialization of VM
Incompatible minimum and maximum heap sizes specified
Picked up _JAVA_OPTIONS: -Xmx512M
Setting MinMemory to 256
Setting MaxMemory to 2048
Error occurred during initialization of VM
Incompatible minimum and maximum heap sizes specified
Picked up _JAVA_OPTIONS: -Xmx512M
The processor is great but that's not even close to enough memory. Even for a small server the minimum is 3 or 4 gigs of memory.
2GB, actually, is the minimum HEAP I recommend for a server. Then add 256m permgen and 512m codecache and effectively raise the bare minimum overall RAM I recommend as 3GB.