1000 times slower API call between in a group and free geometry

AdamB · April 18, 2016, 8:19pm

With no 3rd party plugins installed at all (both Plugins folders renamed on Mac), I still see the same slow timing.

OSX 10.11.4 SketchUp 2016.0.19913

Adam

AdamB · April 18, 2016, 8:21pm

OSX version?

Sketchup version?

AdamB · April 18, 2016, 8:22pm

Same result with no plugins installed.

AdamB · April 18, 2016, 8:32pm

I’ve also tried SketchUp 2015 and get the exact same hang.

However, Sketchup 2014 works fine.

Adam

AdamB · April 18, 2016, 8:34pm

Also, just to sanity check, you are using my modifed script, not the original. Its important to generate mesh normals to trigger this.

module MeshPerformanceTests

  def self.run(iterations = 1)
    iterations.times {
      self.run_test
    }
  end

  def self.run_test
    puts "\n#{self}"
    model = Sketchup.active_model
    definition = model.definitions.first

	Sketchup.active_model.start_operation("MeshTest", true)
	Sketchup.active_model.set_attribute(:meaning, :life, 42);	

    puts "\n> Testing model.entities:"
    result = self.time(model.entities)
    puts "> Time: #{result}s"

    puts "\n> Testing definition.entities:"
    result = self.time(definition.entities)
    puts "> Time: #{result}s"

	Sketchup.active_model.commit_operation
	
  end

  def self.time(entities)
    start = Time.now

    num_triangles = 0
    num_edges = 0
    entities.grep(Sketchup::Face) { |face|
      mesh = face.mesh(7)
	  pos = mesh.points
	  uv0 = mesh.uvs(true)
	  uv1 = mesh.uvs(false)
	  tris = mesh.polygons

	  edges = face.edges
	  edges.each {|e|
        e.start.position
        e.end.position
        num_edges += (e.visible? ? 1 : 0)
	  }

      tris.each {|t| 
		for index in 0...2
	        pos[t[index]]
	        mesh.normal_at(t[index]+1)
			uv0[t[index]]
	        uv1[t[index]]
		end

	  }
      num_triangles += tris.count
    }
    puts "#{entities} contains #{num_triangles} triangles"

    Time.now - start
  end

end # module

john_drivenupthewall · April 18, 2016, 8:42pm

snap on OSX, but M1 on SU i.e. 16.1.1451

using TT’s last set true then false

> MeshPerformanceTests.run(10, true)

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.477028s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.478291s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.410597s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.40697s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.409842s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.424444s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.41269s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.410703s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.465524s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.414035s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.415552s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.413223s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.418112s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.414684s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.416838s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.4124s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.414979s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.411131s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.409765s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.410698s
10
> MeshPerformanceTests.run(10, false)

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.411382s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.405142s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.408692s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.41025s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.414318s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.41526s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.556313s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.52759s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.407285s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.40442s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.406831s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.405581s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.410829s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.408164s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.460376s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.41219s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.411045s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.405952s

MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 0.406767s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.404471s
10
>

AdamB · April 18, 2016, 8:48pm

SketchUp 2016.0.19912

Windows 10

Runs MeshPerformanceTests fine without set_attribute, hangs with set_attribute

DanRathbun · April 19, 2016, 1:07am

Why are you running / testing on an obsolete version ?

I tested on … Win7 64-bit, SketchUp 2016.1.1449 64-bit

I ran this script you posted in post:
http://forums.sketchup.com/t/1000-times-slower-api-call-between-in-a-group-and-free-geometry/22442/13
as modified by Thomas in the following post:
http://forums.sketchup.com/t/1000-times-slower-api-call-between-in-a-group-and-free-geometry/22442/14

However, I missed his initial statement in post:
http://forums.sketchup.com/t/1000-times-slower-api-call-between-in-a-group-and-free-geometry/22442/12

… and then his test code in post #14 has just mesh = face.mesh

So, I change that line to: mesh = face.mesh(7)
and run with modify argument false:

ThomThom::MeshPerformanceTests.run(10)

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.724042s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.769044s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.685039s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.635036s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.677039s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.638037s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.771045s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.630036s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.71104s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.641036s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.69104s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.628036s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.830048s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.630036s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.653037s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.629036s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.655037s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.617035s

ThomThom::MeshPerformanceTests

> Testing model.entities:
#<Sketchup::Entities:0x0000000aad1100> contains 58569 triangles
> Time: 0.676039s

> Testing definition.entities:
#<Sketchup::Entities:0x0000000048b908> contains 58569 triangles
> Time: 0.615035s
10

ThomThom_Mesh_Test.rb (1.1 KB)

Running with the modify argument true just locks up SketchUp.

DanRathbun · April 19, 2016, 1:52am

Here is an example “attribute write within undo” test that does NOT lock up SketchUp:
Dan_AttribUndo_Test.rb (1.0 KB)

module Dan; end
module Dan::AttributeUndoTests

  extend self
  
  DICT = self.name
  
  # Dan::AttributeUndoTests.run(10)

  def run(iterations = 1)
    run_test(iterations)
  end

  def run_test(iterations)
    puts "\n#{self}"
    model = Sketchup.active_model
    
    start = @running = Time.now

    iterations.times {|i|

      model.start_operation(
        "Set Attributes",
        true,  # disable the UI updates
        false, # just let subsequent operations handle the chaining
        i > 0  # true except for the first iteration
      )
      #
      ###
        #
        model.set_attribute( DICT, "loop #{i}", (Time.now - @running).to_s )
        #
      ###
      #
      Sketchup.active_model.commit_operation
      @running = Time.now
    }
    
    duration = Time.now - start
    puts "\n> Test duration: #{duration} secs Total."

    iterations.times {|i|
      puts "  > loop #{i}: #{model.get_attribute( DICT, "loop #{i}")} secs"
    }
    puts()

    @running = nil

  end
  
end

john_drivenupthewall · April 19, 2016, 2:47am

Dan’s v1, eventually resolved…

> Testing model.entities:
#<Sketchup::Entities:0x007faa21fab090> contains 58569 triangles
> Time: 966.112729s

> Testing definition.entities:
#<Sketchup::Entities:0x007faa1efb3658> contains 58569 triangles
> Time: 0.671304s

DanRathbun · April 19, 2016, 3:40am

You mean the one wrapped in the ThomThom module ?

And it took 16 minutes+ to finish, on your Mac, with the modify argument set true ?

AdamB · April 19, 2016, 6:59am

OK good, so it is a bug that is reproducible.

@DanRathbun, its not an exercise in finding a way around it, so much as giving Trimble a repro so they can dig in and find out what the heck is going on that takes so very long.

tt_su · April 19, 2016, 10:37am

Ach! I’d missed the face.mesh(7) in my last test. When added back in I can finally reproduce this. (In fact, it was so bad that I gave up waiting for it…)

I’ve logged this internally as SU-33848. Need to dig into the debugger and profiler to figure out what goes on here.

tt_su · April 19, 2016, 10:38am

I think that eventually you’ll flood the undo stack - as the intermediate operations you create with making operation transparent counts towards the 100 max limit.

AdamB · April 19, 2016, 11:09am

Thanks TT!

May be worth capturing in the bug report that weirdly, if you ENABLE GUI updates in the Undo transaction, there is no significant delay/hang - which is the complete opposite you’d expect.

thomthom · April 19, 2016, 1:52pm

Yes - that’s a good point. A quick initial stepping through the debugger shows that internally when you get face.mesh(7) within an operation that modifies the model there is an internal flag that force update every time vertex normals are requested. Still unclear why this appear to manifest in the root and not when not modifying the model.

thomthom · April 19, 2016, 1:53pm

I’m guessing here, but maybe modifying the model turn that flag on and the disable_ui preserves preserves it across the operation. While without it the flag get reset.

AdamB · April 19, 2016, 3:58pm

Yes and these are read-only calls to extract geometry info. Why is it being marked as a modification?

DanRathbun · April 19, 2016, 4:11pm

Entertaining the idea of exposing this flag to allow developers to choose to enable or disable it, how would ya’ll think it best be implemented ?

a Geom::PolygonMesh::update_vertex_normals= class boolean setter method ?
an extra (new) argument to the Sketchup::Model#start_operation method ? *
an extra (new) argument to the Sketchup::Face#mesh method ? *

( * : … and while at it rewrite argument handling to allow hash arguments. )

… or some other way ?

thomthom · April 19, 2016, 4:23pm

It doesn’t - it’s the attribute you set. That’s an undoable operation. Without that there is no slowdown. So the flag is caused by an actual model change (even though it’s not visual geometry).

This shouldn’t really be needed to be exposed. It’s an internal implementation detail for which we clearly have a really bad performance bug.