Confirmed Pet Melee Lag

Discussion in 'Bug Reports' started by Sancus, Oct 25, 2019.

  1. Sancus Augur

    Summary: Pets have a significant issue with lag in most modern raids. In many of these situations, they swing at a significantly slower rate than they are intended to. It's not uncommon to see 10+ seconds in between pet swings. This drastically reduces their DPS output, both from melee DPS and from procs. This only happens to "main" pets; swarm pets do not appear to experience comparable lag.
    ______________________________________

    I originally made a post about this issue here, and it was the highest voted unresolved bug on the issue tracker prior to it going down. It's been an issue since at least TDS, and has worsened as zone performance has generally deteriorated. It is common for pets to swing at fractions of the rate that they "should" swing at, compared to swing rates on Combat Dummies or in group content.

    First, here is a parse from a combat dummy to demonstrate expected behavior (709 second duration):

    Puksu -vs- Combat Dummy Meda II: -- DMG: 33827211 -- DPS: 47711 -- Scaled: 47711 -- Slash: 24513237 -- Backstab: 8700668 -- DirDmg: 613306 -- % dmg as normal: 21.3% -- % dmg as critical: 78.7% -- Non-crit rate: 55.4% -- crit rate: 44.6% -- Attempts: 2736 -- Hits: 2530 -- Missed: 206 -- Accuracy: 92.5% -- Avg Hit: 13370 -- Max hit: 131770 -- DMG to PC: 0

    2342 of those attempts were slashes, which equates to 3.3 attempts per second. Here were my pet's casts:

    Combat Dummy Meda II on 10/25/2019

    Puksu (Sancus) - 185
    --- Iceflame Strike Caza VIII - 97
    --- Water Elemental Strike XII - 88

    That's an iceflame proc every 7.3 seconds under normal behavior. Water Elemental Strike cast every 8.05 seconds. Both of these metrics are without Frenzied Burnout; slash attempts would be higher were it running.

    To compare, here is some data from recent TBL raids. I want to begin with the graphs because they illustrate how severe the problem is - there are multiple 30+ second gaps in between pet melee attempts on this graph.

    [IMG]

    [IMG]

    Digging into the numbers from the latter graph (Aalishai), here is my pet's melee and cast parses:

    Puksu -vs- Seneschal Radiant Propensity: -- DMG: 5595533 -- DPS: 19912 -- Scaled: 18903 -- Slash: 2452563 -- Backstab: 1605279 -- DirDmg: 1530264 -- Environmental: 7427 -- % dmg as normal: 44.5% -- % dmg as critical: 55.5% -- Non-crit rate: 62.6% -- crit rate: 37.4% -- Attempts: 133 -- Hits: 115 -- Missed: 4 -- Defended: 14 -- Accuracy: 96.6% -- Avg Hit: 48656 -- Max hit: 438053 -- DMG to PC: 1383939

    Seneschal Radiant Propensity on 10/6/2019

    Puksu (Sancus) - 26
    --- Arcane Ballad Strike III - 4
    --- Companion's Assault XXXI - 4
    --- Iceflame Strike Caza VIII - 2
    --- Storm Blade Strike - 4
    --- Travenro's Strike III - 1
    --- Virulent Talon Strike IV - 10
    --- Water Elemental Strike XII - 1

    Here's a comparison between my combat dummy parse (which did not have FBO):
    • Instead of making 3.3 slash attempts per second, my pet made 0.3 slash attempts per second (89 of those attempts were slash attempts). In other words, he swung at about 1/11th the rate he should have.
    • Iceflame averaged a proc every 148 seconds, as compared to a proc every 7.3 seconds.
    • Water Elemental Strike cast every 29.6 seconds, as compared to a cast every 8.05 seconds.
    • Virulent Talon did not consume all 15 of its procs over the 5 minutes this fight ensued.
    This really hampers pet class DPS in raids, and also contributes significantly to the variability in our DPS. This makes tuning pet-based upgrades extremely difficult, because many of them have almost no impact in raids. Despite numerous upgrades to pets, their sustained DPS in such situations is below what it was in Call of the Forsaken. I know zone lag is a very difficult issue to fix, but it's extremely detrimental to the experience of raiding in EQ, and it seems to be a bug that zone lag causes "main" pets to skip swings (whereas normal melee and swarm pet melee do not).

    I appreciate your consideration.
  2. Duder Augur

    Thanks for this post Sancus, would love to see some sort of resolution or at the very least, an effort to resolve this. Maybe even an acknowledgement?
    Hobs, Shard and Sancus like this.
  3. MarttinPH Augur

    Amazing amount of research!
    Hobs, minimind, Shard and 1 other person like this.
  4. Raneern Journeyman

    Great information and completely agree!
    Hobs, Shard and Sancus like this.
  5. Rikkitikkitavi Journeyman

    Thank you, Sancus. Your willingness and ability to validate your concerns serves us all so very very well.
    Hobs, Shard and Sancus like this.
  6. Malbro Augur

    Thank you Sancus, I have seen this myself.
    Hobs, Shard and Sancus like this.
  7. Metapsyche Augur

    Bump. WTB: More Sancus DPS... gimpy mage
    Shard and Sancus like this.
  8. JChan Developer

    This is a symptom of deeper performance issues. We're actively working on improving these issues, however we do not expect a resolution any time soon.
    Hobs, Carden, Shard and 8 others like this.
  9. JChan Developer

    Sancus, could you also do another test / analysis for your next raid? We brought online a little bit more hardware on 10/25 and have been directing new traffic to it. (Also please include the world, raid name, and date and time for the next analysis.)
    Hobs, Shard, Bardy McFly and 5 others like this.
  10. Mintalie Augur

    This is exciting!
    Shard likes this.
  11. mackal Augur

    What if it buffs raid mob DPS!
    Shard and Bardy McFly like this.
  12. Sancus Augur

    Absolutely. Next raid will be Sunday, 11/3 on Xegony. I will include the rest of the information in the analysis once the raid occurs.

    I don't know that this is at all useful information, but will mention this anyway: very occasionally, we will experience raid instances where pets do not lag nearly to the extent I described in the OP. At this point the example is old, but we had one instance of the Fell Foliage raid (from The Overthere zone in RoS) on August 12th, 2018 where my pet experienced relatively little lag. Essentially every other week on that raid my pet exhibited behavior comparable to what I described in the first post (i.e., it lagged significantly).

    If it would be helpful, I can go through logs from more recent raids to try and find any similar situations where my pet did perform as expected. Alternatively, I can look out for those situations in the future and post details here if it occurs again. Whatever is most useful (if any of it).

    Thank you for looking at this.
    Hobs, Shard, Ryino and 1 other person like this.
  13. JChan Developer

    Let's just get a new analysis first and start from there. What we're hoping to do with this information is to correlate it with the internal data we have and try to narrow this down a bit more.
    Hobs, Shard, Duder and 7 others like this.
  14. Sancus Augur

    All raids listed here took place yesterday, November 3rd, on the Xegony server.

    Dragon in the Works

    The first raid was Dragon in the Works, the first raid in the Gnome Memorial Mountain: Danger Zone raid instance. We engaged the raid at 4:37:09 PM Pacific Time (7:37:09 PM Eastern). Here is a graph of my pet's (Puksu's) damage during that raid:

    [IMG]

    The duration of the raid was 189 seconds, during which Puksu made 94 slash attempts. In the Rustbottom in the original post the fight was 185 seconds and he made 31 slash attempts. That's 0.497 slash attempts per second last night, relative to 0.168 attempts per second on October 6th. Here are his casts:

    Rustbottom, Grinder of Gears on 11/3/2019

    Puksu (Sancus) - 6
    --- Arcane Ballad Strike - 2
    --- Received Auspice of the Hunter - 1
    --- Received Bard Epic - 1
    --- Received Black Wolf - 1
    --- Received Chromatic Haze - 1
    --- Received Chromatic Haze Proc - 4
    --- Received Illusions of Grandeur - 1
    --- Received Quick Time - 1
    --- Travenro's Strike - 1
    --- Virulent Talon Strike IV - 1
    --- Water Elemental Strike XII - 2

    He had Maloseniac Eminence on him, which is comparable to Iceflame Eminence used in the original post (Maloseniac has a slightly higher proc rate mod, 250% vs 200%). That did not proc at all during the 189 second duration (Iceflame procced twice on October 6th). Water Elemental Strike cast twice, compared to once on the Rustbottom fight on October 6th. With such low #'s of procs, I think it makes more sense to look at the number of slash attempts to properly compare.

    The Palace Gates

    This raid was The Palace Gates in the Aalishai zone. We engaged the raid at 7:36:02 PM Pacific Time (10:36:02 PM Eastern Time). My pet died at 8% on the boss ([Sun Nov 03 22:40:18 2019] Puksu has been slain by Seneschal Radiant Propensity!), 256 seconds after engaging. I will use that duration as the denominator for slashes per second and casts per second. Here's the graph of the fight:

    [IMG]

    Here's the melee and cast data from this fight:

    /tell Sancus Puksu -vs- Seneschal Radiant Propensity: -- DMG: 8270325 -- DPS: 33894 -- Scaled: 27752 -- Slash: 4302796 -- Backstab: 2761974 -- DirDmg: 1205555 -- % dmg as normal: 28.1% -- % dmg as critical: 71.9% -- Non-crit rate: 46.9% -- crit rate: 53.1% -- Attempts: 177 -- Hits: 175 -- Missed: 2 -- Accuracy: 98.9% -- Avg Hit: 47259 -- Max hit: 585129 -- DMG to PC: 2379930

    Seneschal Radiant Propensity on 11/3/2019

    Puksu (Sancus) - 23
    --- Arcane Ballad Strike - 6
    --- Companion's Assault XXXI - 2
    --- Iceflame Strike Caza VIII - 5
    --- Received Auspice of the Hunter - 1
    --- Received Black Wolf - 1
    --- Received Chromatic Haze - 2
    --- Received Chromatic Haze Proc - 7
    --- Received Illusions of Grandeur - 2
    --- Received Paragon - 1
    --- Received Quick Time - 1
    --- Travenro's Strike - 2
    --- Virulent Talon Strike IV - 8

    Some comparisons:
    • My pet made 134 slash attempts, which is 0.52 per second, compared to 0.3 per second on October 6th.
    • My pet procced Iceflame Strike on average once every 51.2 seconds, compared to once every 148 seconds on October 6th (obviously with such low overall # of procs this is pretty variable).
    • Water Elemental Strike did not cast at all. I made a mistake in my original post; it only cast once during the October 6th Aalishai raid.
    Prince Ralaifin

    This is the first raid in the Empyr: Realms of Ash raid instance. We engaged it at 6:53:27 PM Pacific Time (9:53:27 PM Eastern Time). I thought it prudent to include this briefly because my pet performed relatively better than the two aforementioned raids, and in general the instance felt less laggy. This raid involves some movement from boss to boss, but my put made approximately twice as many slash attempts per second when compared to the previous two raids.

    Over 574 seconds he made 719 slash attempts, a rate of 1.26 per second. He cast Iceflame Strike 24 times, which is a proc every 23.92 seconds. If it helps to provide additional details from this raid, I can do so.

    Hopefully that information is useful. Please let me know if there's any other data I can provide from last night (or others) that would help. Thank you for your time.
    ChiiChii, Hobs, Shard and 9 others like this.
  15. JChan Developer

    Thanks for detailed information. We've aligned this with our internal data and definitely see the performance issues. Now to add more diagnostics and drill further into what's causing our raid zone bottlenecks!
    Hobs, Raccoo, Waitwhat and 12 others like this.
  16. Numiko Augur

    Jenn is like the Sherlock Holmes of Everquest,

    I can just picture her yelling "The Game is Afoot!" when starting to chasing down and squash bugs ...
    Hobs, Svann2, Skuz and 2 others like this.
  17. Mintalie Augur

    Last night GMM3, lag was mediocre, pet was just sitting there, chilling. Can confirm pet melee problems!
    Shard likes this.
  18. Eryssel Journeyman

    Bump
    Shard likes this.
  19. Ratalthor Developer

    We've made improvements since this post. If you're still seeing this issue, can you share what server and event you're running and roughly what time the issue occurred?
  20. Sancus Augur

    I have not seen material improvements to pet lag (or raid zone lag) since this bug report. I appreciate the effort in addressing this, but anecdotally I've actually found performance worse recently.

    Both raids in this post took place yesterday, August 10th on the Xegony server.

    Restless Avatar of War

    At 17:02:59 Pacific Time we began the Restless Avatar of War raid in the Kael Drakkel raid instance. Here is a graph of my pet's (Puksu's) damage during that raid:

    [IMG]

    Note the numerous gaps in activity, often stretching for longer than 30 seconds. My pet had 430 attempts over the course of the event, of which 306 were melee attacks:

    /tell Puksu Puksu -vs- Combined: Icebound Avatar of War: -- DMG: 21446167 -- DPS: 27816 -- Scaled: 27389 -- Backstab: 10137356 -- Pierce: 7843057 -- DirDmg: 3003490 -- Environmental: 462264 -- % dmg as normal: 28.9% -- % dmg as critical: 71.1% -- Non-crit rate: 62% -- crit rate: 38% -- Attempts: 430 -- Hits: 413 -- Missed: 5 -- Defended: 12 -- Accuracy: 98.8% -- Avg Hit: 51927 -- Max hit: 819396 -- DMG to PC: 1337258

    The duration of the raid was 783 seconds. My pet performed 0.391 melee attempts per second, relative to ~0.5 melee attempts per second in my last post and 3.3 attempts per second on a combat dummy. Here are my pet's casts:

    Combined: Icebound Avatar of War on 8/9/2020

    Puksu - 73
    --- Allied Elemental Strike IV - 1
    --- Arcane Symphony Strike III - 10
    --- Companion's Elemental Strike IV - 2
    --- Iceflame Strike Beza IX - 11
    --- Omorden's Strike III - 7
    --- Received Auspice of the Hunter - 1
    --- Received Bard Epic - 3
    --- Received Chromatic Haze - 1
    --- Received Chromatic Haze Proc - 7
    --- Received Illusions of Grandeur - 1
    --- Received Paragon - 1
    --- Received Quick Time - 2
    --- Storm Blade Strike - 13
    --- Virulent Talon Strike V - 26
    --- Water Elemental Strike XIII - 3

    My pet performed an Iceflame Strike cast every 71.18 seconds, versus every 7.3 seconds on a combat dummy. Puksu cast Water Elemental Strike every 261 seconds, versus every 8.05 seconds on a combat dummy.

    Seeking the Sorcerer

    We began Seeking the Sorcerer in the Velketor's Labyrinth: Seeking the Sorcerer raid instance at 17:33:13 Pacific Time. Here's a graph of my pet's damage on the first mob, noting that as part of our raid strat the first 22 seconds I intentionally did not have him attack:

    [IMG]

    He had a 33 second gap in his melee swings, after which he did not swing for the rest of the fight. Here are the logs of the entirety of his offensive/casting actions during that period (note that the timestamps are Eastern Time):
    Code:
    [Sun Aug 09 20:33:35 2020] Puksu told you, 'Attacking Restless Tijoely Master.'
    [Sun Aug 09 20:33:35 2020] Puksu hit Restless Tijoely for 225 points of fire damage by Flame Strike.
    [Sun Aug 09 20:33:35 2020] Puksu pierces Restless Tijoely for 13536 points of damage.
    [Sun Aug 09 20:33:35 2020] Puksu pierces Restless Tijoely for 30078 points of damage. (Lucky Critical)
    [Sun Aug 09 20:33:35 2020] Puksu pierces Restless Tijoely for 47179 points of damage. (Critical Flurry)
    [Sun Aug 09 20:33:35 2020] Puksu tries to pierce Restless Tijoely, but misses! (Flurry)
    [Sun Aug 09 20:33:35 2020] Puksu pierces Restless Tijoely for 16632 points of damage. (Lucky Critical)
    [Sun Aug 09 20:33:35 2020] Puksu pierces Restless Tijoely for 22036 points of damage. (Critical)
    [Sun Aug 09 20:33:35 2020] Puksu backstabs Restless Tijoely for 201573 points of damage. (Critical)
    [Sun Aug 09 20:33:35 2020] Puksu told you, 'Attacking Restless Tijoely Master.'
    [Sun Aug 09 20:33:35 2020] Puksu told you, 'Attacking Restless Tijoely Master.'
    [Sun Aug 09 20:33:36 2020] Puksu pierces Restless Tijoely for 77578 points of damage. (Lucky Critical)
    [Sun Aug 09 20:33:36 2020] Puksu pierces Restless Tijoely for 17740 points of damage.
    [Sun Aug 09 20:33:36 2020] Puksu pierces Restless Tijoely for 17740 points of damage. (Flurry)
    [Sun Aug 09 20:33:36 2020] Puksu pierces Restless Tijoely for 24239 points of damage. (Critical Flurry)
    [Sun Aug 09 20:33:36 2020] Puksu pierces Restless Tijoely for 11327 points of damage.
    [Sun Aug 09 20:33:37 2020] Reisil healed Puksu for 0 (11820) hit points by Blessing of the Ancients III.
    [Sun Aug 09 20:33:37 2020] Puksu invokes the spirit of the great wolf.
    [Sun Aug 09 20:33:37 2020] Puksu pierces Restless Tijoely for 33063 points of damage. (Lucky Critical)
    [Sun Aug 09 20:33:37 2020] Puksu pierces Restless Tijoely for 14149 points of damage.
    [Sun Aug 09 20:33:37 2020] Puksu pierces Restless Tijoely for 64197 points of damage. (Lucky Critical)
    [Sun Aug 09 20:33:39 2020] Puksu begins casting Iceflame Strike Beza IX.
    [Sun Aug 09 20:33:39 2020] Puksu hit Restless Tijoely for 6507 points of cold damage by Iceflame Strike Beza IX.
    [Sun Aug 09 20:33:39 2020] Puksu begins casting Virulent Talon Strike V.
    [Sun Aug 09 20:33:39 2020] Puksu hit Restless Tijoely for 120000 points of poison damage by Virulent Talon Strike V.
    [Sun Aug 09 20:33:39 2020] Puksu pierces Restless Tijoely for 14805 points of damage.
    [Sun Aug 09 20:33:39 2020] Puksu pierces Restless Tijoely for 61884 points of damage. (Critical)
    [Sun Aug 09 20:33:39 2020] Puksu pierces Restless Tijoely for 87801 points of damage. (Lucky Critical Flurry)
    [Sun Aug 09 20:33:39 2020] Puksu pierces Restless Tijoely for 87559 points of damage. (Lucky Critical Flurry)
    [Sun Aug 09 20:34:12 2020] Puksu begins casting Virulent Talon Strike V.
    [Sun Aug 09 20:34:12 2020] Puksu hit Restless Tijoely for 134400 points of poison damage by Virulent Talon Strike V.
    [Sun Aug 09 20:34:12 2020] Puksu pierces Restless Tijoely for 18003 points of damage.
    [Sun Aug 09 20:34:12 2020] Puksu pierces Restless Tijoely for 2467 points of damage.
    [Sun Aug 09 20:34:12 2020] Puksu pierces Restless Tijoely for 106683 points of damage. (Critical Flurry)
    [Sun Aug 09 20:34:12 2020] Puksu pierces Restless Tijoely for 7036 points of damage. (Flurry)
    [Sun Aug 09 20:34:12 2020] Puksu backstabs Restless Tijoely for 962674 points of damage. (Critical)
    On the final boss, Bled Enraged, there was an 84 second gap between the attack command and the first time he did damage:

    [Sun Aug 09 20:44:28 2020] Puksu told you, 'Attacking Bled Enraged Master.'
    [Sun Aug 09 20:45:52 2020] Puksu hit Bled Enraged for 270 points of fire damage by Flame Strike.

    I appreciate your efforts in looking into and addressing zone performance in raids. Let me know if there's any other information that might be of value. This occurs in essentially all of our raids.