Policy continues to dominate steady state operation

[smarterclayton]

Heap allocation of objects after about 2 minutes of hack/test-cmd.sh command on etcd3 with protobuf (where most of the object allocations from etcd have dropped out). 25m allocations total.

A non-trivial amount of CPU was in SetDefaults_PolicyRule on the SemanticDeepEqual which calls into reflection.

   5366883 20.83% 20.83%    5366883 20.83%  github.com/openshift/origin/pkg/authorization/api/v1.(*PolicyRule).Unmarshal
   2605126 10.11% 30.95%    2605126 10.11%  math/big.putNat
   1637218  6.36% 37.30%    1637218  6.36%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/sets.String.Insert
   1409077  5.47% 42.77%    1543799  5.99%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/sets.NewString
   1333840  5.18% 47.95%    1694288  6.58%  github.com/openshift/origin/pkg/authorization/api/v1.SetDefaults_PolicyRule
   1321695  5.13% 53.08%    5862017 22.76%  github.com/openshift/origin/pkg/authorization/api/v1.Convert_v1_PolicyRule_To_api_PolicyRule
    739931  2.87% 55.95%     739931  2.87%  reflect.unsafe_New
    578443  2.25% 58.20%     578443  2.25%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/api/v1.(*ObjectMeta).Unmarshal
    508727  1.97% 60.17%     508727  1.97%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/sets.String.List
    333511  1.29% 61.47%    5968004 23.17%  github.com/openshift/origin/pkg/authorization/api/v1.(*ClusterRole).Unmarshal

[smarterclayton]

From a minute later at 38m total allocations, this time cumulatively sorted:

     32769 0.085% 0.085%    8290398 21.42%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/runtime/serializer/protobuf.(*Serializer).Decode
         0     0% 0.085%    8150396 21.06%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/runtime/serializer/protobuf.unmarshalToObject
         0     0% 0.085%    8140162 21.03%  github.com/openshift/origin/vendor/github.com/gogo/protobuf/proto.Unmarshal
         0     0% 0.085%    8140162 21.03%  github.com/openshift/origin/vendor/github.com/gogo/protobuf/proto.UnmarshalMerge
     72094  0.19%  0.27%    8096758 20.92%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/conversion.(*Converter).Convert
     42130  0.11%  0.38%    7688617 19.86%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/runtime/serializer/recognizer.(*decoder).Decode
         0     0%  0.38%    7390997 19.09%  github.com/openshift/origin/pkg/api/install.init.1.func1
         0     0%  0.38%    7374326 19.05%  github.com/openshift/origin/pkg/cmd/server/origin.(*MasterConfig).authorizationFilter.func1
         0     0%  0.38%    7189671 18.57%  github.com/openshift/origin/pkg/authorization/rulevalidation.ConfirmNoEscalation
         0     0%  0.38%    6860421 17.72%  github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).dispatch
         0     0%  0.38%    6843566 17.68%  github.com/openshift/origin/vendor/github.com/emicklei/go-restful.(*Container).(github.com/openshift/origin/vendor/github.com/emicklei/go-restful.dispatch)-fm
         0     0%  0.38%    6691196 17.29%  github.com/openshift/origin/pkg/authorization/rulevalidation.(*DefaultRuleResolver).GetRole
     15025 0.039%  0.42%    6669366 17.23%  github.com/openshift/origin/pkg/authorization/rulevalidation.(*DefaultRuleResolver).GetEffectivePolicyRules
         0     0%  0.42%    6583527 17.01%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/apiserver.(*namedCreaterAdapter).Create
         0     0%  0.42%    6578846 17.00%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/apiserver.createHandler.func1.1
         0     0%  0.42%    6508655 16.82%  github.com/openshift/origin/pkg/authorization/registry/clusterpolicy.(*ReadOnlyClusterPolicy).Get
         0     0%  0.42%    6508655 16.82%  github.com/openshift/origin/pkg/authorization/registry/clusterpolicy.ReadOnlyClusterPolicy.Get
         0     0%  0.42%    6460558 16.69%  github.com/openshift/origin/pkg/authorization/api/v1.Convert_v1_ClusterPolicy_To_api_ClusterPolicy
    136158  0.35%  0.77%    6460558 16.69%  github.com/openshift/origin/pkg/authorization/api/v1.Convert_v1_NamedClusterRoles_To_api_ClusterRolesByName
         0     0%  0.77%    6460558 16.69%  github.com/openshift/origin/pkg/authorization/api/v1.autoConvert_v1_ClusterPolicy_To_api_ClusterPolicy
     19781 0.051%  0.82%    6384654 16.50%  github.com/openshift/origin/pkg/authorization/api/v1.(*ClusterPolicy).Unmarshal
     76460   0.2%  1.02%    6364873 16.44%  github.com/openshift/origin/pkg/authorization/api/v1.(*NamedClusterRole).Unmarshal
     32768 0.085%  1.10%    6348752 16.40%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/runtime.(*Scheme).Convert
         0     0%  1.10%    6341513 16.38%  github.com/openshift/origin/pkg/authorization/api/v1.Convert_v1_ClusterRole_To_api_ClusterRole
    131398  0.34%  1.44%    6341513 16.38%  github.com/openshift/origin/pkg/authorization/api/v1.autoConvert_v1_ClusterRole_To_api_ClusterRole
    359001  0.93%  2.37%    6288413 16.25%  github.com/openshift/origin/pkg/authorization/api/v1.(*ClusterRole).Unmarshal
   1376311  3.56%  5.93%    6210115 16.04%  github.com/openshift/origin/pkg/authorization/api/v1.Convert_v1_PolicyRule_To_api_PolicyRule
         0     0%  5.93%    6155056 15.90%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/runtime.unsafeObjectConvertor.Convert
     21846 0.056%  5.98%    6130432 15.84%  github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/apiserver/metrics.InstrumentRouteFunc.func1

[smarterclayton]

By comparison, out of 6.3gb allocated byte wise, etcd3 was 2gig and GetClusterPolicy() represented 1.2gig.

[smarterclayton]

I added a metric for raw policy retrievals via the Registry (of each of the three types) and the early admin.sh test generated ~1.6k retrievals to the Registry, while 1k of ReadOnlyStorage and ~600 of Simulated.

Looks like every time we create a project we do 30-50 retrievals of the direct cluster policy and the same amount to simulated.

[smarterclayton]

Is there a reason we bust through to the underlying cluster policy on project creation (specifically project request)?

[deads2k]

Is there a reason we bust through to the underlying cluster policy on project creation (specifically project request)?

Yes. We hit the live data to perform covers checks when adding rolebindings.

[smarterclayton]

Do we need to do 30-50 of them (I assume 20 is the delete and 30 is the create)?

[deads2k]

Do we need to do 30-50 of them (I assume 20 is the delete and 30 is the
create)?

Well, I haven't actually counted them. You have to pull all the rolebindings and then some of the roles. It's entirely possible its inefficient because someone made us use virtual objects which necessitated some pretty insane storage layers....

[deads2k]

Do we need to do 30-50 of them (I assume 20 is the delete and 30 is the
create)?

Oh, and given 4 rolebindings, its only 8 requests per. That doesn't sound as crazy.

[smarterclayton]

It hath been slain.

[enj]

@mfojtik Do I actually need to do something for this issue? Seems like @smarterclayton already took care of it?

[smarterclayton]

This is done.